Flush output streams upon process termination

[zturner]

Summary

Due to what can only be described as a CRT bug, stdout and amazingly even stderr are not always flushed upon process termination, especially when the system is under high threading pressure. I have found two repros for this:

1. In lib\Support\Threading.cpp, change sys::Mutex to an std::recursive_mutex and run check-clang. Usually between 30 and 40 tests will fail.
2. Add OutputDebugStrings in code that runs during static initialization and static shutdown. This will sometimes generate similar failures.

After a substantial amount of troubleshooting and debugging, I found that I could reproduce this from the command line without running check-clang. Simply make the mutex change described in #1, then manually run the following command many times by running it once, then pressing Up -> Enter very quickly:

D:\src\llvm\build\vs2013\Debug\bin\c-index-test.EXE -cursor-at=D:\src\llvm\tools\clang\test\Index\targeted-preamble.h:2:15 D:\src\llvm\tools\clang\test\Index\targeted-cursor.c -include D:\src\llvm\build\vs2013\tools\clang\test\Index\Output\targeted-cursor.c.tmp.h -Xclang
-error-on-deserialized-decl=NestedVar1 -Xclang -error-on-deserialized-decl=TopVar | D:\src\llvm\build\vs2013\Debug\bin\FileCheck.EXE D:\src\llvm\tools\clang\test\Index\targeted-cursor.c -check-prefix=PREAMBLE-CURSOR1

Sporadically they will fail, and attaching a debugger to a failed instance indicates that stdin of FileCheck.exe is empty.

Note that due to the repro in #2, we can rule out a bug in the STL's mutex implementation, and instead conclude that this is a real flake in the windows test harness.

[thakis]

Did you file an upstream bug?

[rnk]

That's interesting. I think we avoid this problem for most of our binaries
because they use llvm::raw_ostream. It looks like this is only a problem
for C code that has to use C stdio. I think we never write to C stdio from
other atexit handlers, so I think this should work fine.

I also wonder if this was the true cause of http://llvm.org/PR19744.

[zturner]

@thakis: Done. https://connect.microsoft.com/VisualStudio/feedback/details/888893/stdout-and-stderr-are-not-necessarily-flushed-upon-clean-process-exit
@rnk: Interesting. I am incllined to say that yes, that is definitely the same bug.

I think even if we do write to c stdio handlers from other atexit handlers, it should still be fine. Calls to atexit() handlers are serialized, so worst case scenario some *additional* data that was already not getting flushed, still doesn't get flushed. It's still better than the current flakiness in all cases.

Also, I've confirmed with at least 2 other windows engineers that they have experienced both stderr and stdout not flushing on process termination, so apparently this is a "known issue".

[zturner]

Note that I do not even have Cygwin installed, much less on the path.

[zturner]

@rnk: If you're good with this, can you commit it?

[rnk]

lgtm. It seems harmless to work around this problem in MSVCRT stdio in some C test binaries.

[edward-san]

Closing. It was applied in r210225 by rnk.

tools/c-arcmt-test/c-arcmt-test.c

 typedef struct thread_info {
   int argc;
   const char **argv;
   int result;
 } thread_info;
 void thread_runner(void *client_data_v) {
   thread_info *client_data = client_data_v;
   client_data->result = carcmttest_main(client_data->argc, client_data->argv);
-#ifdef __CYGWIN__
-  fflush(stdout);  /* stdout is not flushed on Cygwin. */
-#endif
+}
+
+static void flush_atexit(void) {
+  // stdout, and surprisingly even stderr, are not always flushed on process
+  // and thread exit, particularly when the system is under heavy load.
+  fflush(stdout);
+  fflush(stderr);
 }
 
 int main(int argc, const char **argv) {
   thread_info client_data;
 
+  atexit(flush_atexit);
+
 #if defined(_WIN32)
   if (getenv("LIBCLANG_LOGGING") == NULL)
     putenv("LIBCLANG_LOGGING=1");
   _setmode( _fileno(stdout), _O_BINARY );
 #else
   setenv("LIBCLANG_LOGGING", "1", /*overwrite=*/0);
 #endif
 
   if (getenv("CINDEXTEST_NOTHREADS"))
     return carcmttest_main(argc, argv);
 
   client_data.argc = argc;
   client_data.argv = argv;
   clang_executeOnThread(thread_runner, &client_data, 0);
   return client_data.result;
 }

tools/c-index-test/c-index-test.c

 typedef struct thread_info {
   int argc;
   const char **argv;
   int result;
 } thread_info;
 void thread_runner(void *client_data_v) {
   thread_info *client_data = client_data_v;
   client_data->result = cindextest_main(client_data->argc, client_data->argv);
-#ifdef __CYGWIN__
-  fflush(stdout);  /* stdout is not flushed on Cygwin. */
-#endif
+}
+
+static void flush_atexit(void) {
+  // stdout, and surprisingly even stderr, are not always flushed on process
+  // and thread exit, particularly when the system is under heavy load.
+  fflush(stdout);
+  fflush(stderr);
 }
 
 int main(int argc, const char **argv) {
   thread_info client_data;
 
+  atexit(flush_atexit);
+
 #ifdef CLANG_HAVE_LIBXML
   LIBXML_TEST_VERSION
 #endif
 
   if (getenv("CINDEXTEST_NOTHREADS"))
     return cindextest_main(argc, argv);
 
   client_data.argc = argc;
   client_data.argv = argv;
   clang_executeOnThread(thread_runner, &client_data, 0);
   return client_data.result;
 }