Adding System.out.printlns causes tsan to miss a race?

[Dmitry Vyukov]

On Sun, Jul 21, 2019 at 12:57 PM Jiri Daněk <jdanek at redhat.com> wrote:
>
> On Sun, Jul 21, 2019 at 10:35 AM Jiri Daněk <jdanek at redhat.com> wrote:
>
> > I compiled jdk-tsan with gcc9, because I had issues compiling with clang_8
> > on nixOS. Does that make the test above invalid? I presume I could use
> > ubuntu in docker, if asked.
> >
>
> Managed to compile with clang_8. With the VERBOSE=true, I get the sanitizer
> warning in what feels about 1 in 10 runs. I don't have the gcc9 build any
> more to compare, there I never saw warning with VERBOSE=true, but I did not
> run it many times and I did not try running in a loop.
>
> One of the lucky runs looks like this
>
> $ build/linux-x86_64-server-release/jdk/bin/java -XX:+ThreadSanitizer
> -classpath /home/jdanek/repos/java-sanitizer/out/production/java-sanitizer/
> Main
> Hello World!
> pes
> pes
> pes
> pes
> pes
> 7
> pes
> ==================
> WARNING: ThreadSanitizer: data race (pid=22615)
>   Read of size 4 at 0x00066390da34 by thread T14:
>     #0 Main.lambda$main$0(LMain$1;)V Main.java:13
>     #1 Main$$Lambda$36.run()V ??
>     #2 java.lang.Thread.run()V Thread.java:835
>     #3 (Generated Stub) <null>
>
>   Previous write of size 4 at 0x00066390da34 by thread T1:
>     #0 Main.main([Ljava/lang/String;)V Main.java:22
>     #1 (Generated Stub) <null>
>
>   Thread T14 (tid=22631, running) created by thread T1 at:
>     #0 pthread_create ??:? (java+0x42c5d6)
>     #1 os::create_thread(Thread*, os::ThreadType, unsigned long)
> /home/jdanek/repos/jdk-tsan/src/hotspot/os/linux/os_linux.cpp:774
> (libjvm.so+0xb2683d)
>     #2 java.lang.Thread.start()V Thread.java:804
>     #3 Main.main([Ljava/lang/String;)V Main.java:19
>     #4 (Generated Stub) <null>
>
>   Thread T1 (tid=22617, running) created by main thread at:
>     #0 pthread_create ??:? (java+0x42c5d6)
>     #1 CallJavaMainInNewThread
> /home/jdanek/repos/jdk-tsan/src/java.base/unix/native/libjli/java_md_solinux.c:769
> (libjli.so+0x9cba)
>
> SUMMARY: ThreadSanitizer: data race Main.java:13 in
> Main.lambda$main$0(LMain$1;)V
> ==================
> 7
> pes
> pes
> ThreadSanitizer: reported 1 warnings
> ThreadSanitizer: reported 1 warnings


Hi Jiri,

Yes, this is an unfortunate aspect of happens-before-based race
detectors. But this is the cost for not having false positives.
Inserting something that contains synchronization (esp. global
synchronization) between operations makes detecting races on these
operations harder. We need to catch the racing operations happening
closer in time to catch races, close enough so that there is no
parasitic synchronization in between. Consider, if threads don't do
any synchronization, then tsan should be able to catch racing accesses
even if they happen an hour apart. But the more synchronization is
there, the closer we need to catch them.
The practical consequence: it's useful to run all tests multiple times
and continuously, then all races tend to pop up over time.
If we are talking about unit tests, then they may need to be specially
engineered to trigger races more consistently (in particular, no
printf's ;)).