Complaint about mmdevapi (COM?) logging

[Joerg-Cyril.Hoehle at t-systems.com]

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