[Bug 16941] New: interrupts cause nested trace output

http://bugs.winehq.org/show_bug.cgi?id=16941

Summary: interrupts cause nested trace output
           Product: Wine
           Version: 1.1.12
          Platform: PC
        OS/Version: Linux
            Status: UNCONFIRMED
          Severity: normal
          Priority: P2
         Component: -unknown
        AssignedTo: [e-mail]
        ReportedBy: [e-mail]

The winmm periodic timer interrupt (used e.g. by the dsound PCM player) causes
confusion in wine's debug log. I believe every line in the log should be output
atomically. This is not the case and makes the log harder to analyse.

Please search your traces using the following regexp
.[0-9]{4}:[a-zCR]
to find sections where one thread manages to interrupt another one amid a log
line.

In my case, all such occurrences are caused by one thread, identified as
follows:
0019:trace:mmtime:TIME_MMSysTimeThread Starting main winmm thread

Here's a sample where the main thread's (0009) logline is interrupted by the
timer's thread (0019) trace output:

0009: get_handle_fd(0019:Call KERNEL32.GetTickCount()
0019:Ret  KERNEL32.GetTickCount()
0019:trace:dsound:DSOUND_timer (1,0,0x1fbbb0,0x0,0x0)
0019:[many lines omitted]
 handle=00a4 ) <- This is the remains of the trace output
                  from the interrupted thread (0009)
0009: *fd* 00a4 -> 83

Here's another example, involving a redispatch to thread 0018:

001e0019:Call KERNEL32.GetTickCount() 
0019:Ret  KERNEL32.GetTickCount() ...
0019: [many lines omitted]
: create_key() = 0 { hkey=0020, created=0 }
^^^^  remains from thread 001e
0018: get_new_process_info( info=0038 )
0018: select() = PENDING { timeout=infinite, ...
001e:trace:reg:NtCreateKey <- 0x20

The interruptor's pattern is always the same:
- 2x GetTickCount()
- trace:dsound:DSOUND_timer
- dsound perform mix etc.

Looking at libs/wine/debug.c:default_dbg_vlog() I see no obvious mechanism to
ensure atomic output, while and dlls/ntdll/debugtools.c:NTDLL_dbg_vlog() might
have the machinery given a temporary output buffer and a single call to
write().