Hi,
I'm not satisfied with the current winmm+mmdevapi logging. I suspect that COM logging of other components is similarly bad. Consider the following snippet. It looks like a +relay log, not showing what I want to see.
0022:trace:winmm:waveOutWrite (0xc000, 0x21f140, 32) 0020:trace:winmm:WOD_PushData (0xc000) 0020:trace:alsa:AudioClient_GetBufferSize (0x48f7700)->(0x4b0e9c4) 0020:trace:alsa:AudioClient_GetCurrentPadding (0x48f7700)->(0x4b0e9c8) 0020:trace:alsa:AudioClock_GetFrequency (0x48f7700)->(0x4b0e930) 0020:trace:alsa:AudioClock_GetPosition (0x48f7700)->(0x4b0e928, (nil)) 0020:trace:alsa:AudioClient_GetCurrentPadding (0x48f7700)->(0x4b0e8b4) 0020:trace:alsa:AudioRenderClient_GetBuffer (0x48f7700)->(256, 0x4b0e9c0) 0020:trace:alsa:AudioClient_GetCurrentPadding (0x48f7700)->(0x4b0e938) 0020:trace:alsa:AudioRenderClient_ReleaseBuffer (0x48f7700)->(256, 0) 0020:trace:winmm:WOD_PushData (0xc000)
I don't want those %p pointers, I want values.
- What's the position? - What's the low-level driver's padding? - What's the mmdevapi padding? - How many samples did waveOutWrite() supply? - Where's any log line from the intermittent mmdevapi periodic timer callback? + The current log is easily compressible :-)
The only concrete data is from GetBuffer/ReleaseBuffer: 256 frames, so GetCurrentPadding probably returned GetBuffersize (whose value I derive from the call to Initialize, not shown here) minus 256.
The bad news is that you derive more from what you *don't* see in the log than what's written therein. This costs time and effort. E.g. GetBuffer wasn't called means buffer was full -- wait, perhaps there was no more queued data? Help!
Why do I believe that logging of other COM dlls may be similarly bad? The anti-pattern is to have a TRACE at function entry! I'd rather move that down a few lines, after basic checking of parameters. At that time you can TRACE some meaningful values instead of pointers. Then you may even decide to put the TRACE at the end of the function, e.g. for GetCurrentPadding that makes a lot of sense, without the added cost of two TRACE lines.
Basically, there's little value in an early TRACE because only in rare case will you want to know that the call may have been aborted by E_INVALIDARG or AUDCLNT_E_NOT_INITIALIZED -- not to mention that those return values are almost never logged, not even with +relay.
Actually, the useful amount of logging is a function of code maturity. Initially, you're happy with logging every API call. Once you've tested that the basic input checks work exactly like in native, you want to see more from the inside.
IOW, initial stubs contain nothing but TRACE. When you fill the function body, it is an error to leave the TRACE at the top, it should move down to the heart of the function where the interesting stuff happens.
Regards, Jörg Höhle