Bernhard Loos : ntdll: Provide a timestamp debug channel, which prints a millisecond resolution timestamp in front of debug output.

[Alexandre Julliard]

Module: wine
Branch: master
Commit: 23e1777054f2a801ce14991793cf68b577717deb
URL:    http://source.winehq.org/git/wine.git/?a=commit;h=23e1777054f2a801ce14991793...

Author: Bernhard Loos 
Date:   Thu Sep  1 09:21:06 2011 +0200

ntdll: Provide a timestamp debug channel, which prints a millisecond resolution timestamp in front of debug output.

---

dlls/ntdll/debugtools.c |    8 +++++++-
 dlls/ntdll/relay.c      |   16 ++++++++++++++++
 2 files changed, 23 insertions(+), 1 deletions(-)

diff --git a/dlls/ntdll/debugtools.c b/dlls/ntdll/debugtools.c
index cb08285..dfb44af 100644
--- a/dlls/ntdll/debugtools.c
+++ b/dlls/ntdll/debugtools.c
@@ -39,6 +39,7 @@
 #include "ntdll_misc.h"

WINE_DECLARE_DEBUG_CHANNEL(tid);
+WINE_DECLARE_DEBUG_CHANNEL(timestamp);

static struct __wine_debug_functions default_funcs;

@@ -164,8 +165,13 @@ static int NTDLL_dbg_vlog( enum __wine_debug_class cls, struct __wine_debug_chan
     /* only print header if we are at the beginning of the line */
     if (info->out_pos == info->output || info->out_pos[-1] == '\n')
     {
+        if (TRACE_ON(timestamp))
+        {
+            ULONG ticks = NtGetTickCount();
+            ret = wine_dbg_printf( "%3u.%03u:", ticks / 1000, ticks % 1000 );
+        }
         if (TRACE_ON(tid))
-            ret = wine_dbg_printf( "%04x:", GetCurrentThreadId() );
+            ret += wine_dbg_printf( "%04x:", GetCurrentThreadId() );
         if (cls < sizeof(classes)/sizeof(classes[0]))
             ret += wine_dbg_printf( "%s:%s:%s ", classes[cls], channel->name, function );
     }
diff --git a/dlls/ntdll/relay.c b/dlls/ntdll/relay.c
index 4855a00..3bf7791 100644
--- a/dlls/ntdll/relay.c
+++ b/dlls/ntdll/relay.c
@@ -37,6 +37,7 @@
 #include "wine/debug.h"

WINE_DEFAULT_DEBUG_CHANNEL(relay);
+WINE_DECLARE_DEBUG_CHANNEL(timestamp);

#if defined(__i386__) || defined(__x86_64__)

@@ -396,6 +397,13 @@ __ASM_GLOBAL_FUNC( call_entry_point,
 #endif

+static void print_timestamp(void)
+{
+    ULONG ticks = NtGetTickCount();
+    DPRINTF( "%3u.%03u:", ticks / 1000, ticks % 1000 );
+}
+
+
 /***********************************************************************
  *           relay_call
  *
@@ -414,6 +422,8 @@ static LONGLONG WINAPI relay_call( struct relay_descr *descr, unsigned int idx,
         ret = call_entry_point( entry_point->orig_func, nb_args, stack + 1, flags );
     else
     {
+        if (TRACE_ON(timestamp))
+            print_timestamp();
         if (entry_point->name)
             DPRINTF( "%04x:Call %s.%s(", GetCurrentThreadId(), data->dllname, entry_point->name );
         else
@@ -423,6 +433,8 @@ static LONGLONG WINAPI relay_call( struct relay_descr *descr, unsigned int idx,

ret = call_entry_point( entry_point->orig_func, nb_args, stack + 1, flags );

+        if (TRACE_ON(timestamp))
+            print_timestamp();
         if (entry_point->name)
             DPRINTF( "%04x:Ret  %s.%s()", GetCurrentThreadId(), data->dllname, entry_point->name );
         else
@@ -933,6 +945,8 @@ void WINAPI __regs_SNOOP_Entry( CONTEXT *context )

context->Eip = (DWORD)fun->origfun;

+	if (TRACE_ON(timestamp))
+		print_timestamp();
    if (fun->name) DPRINTF("%04x:CALL %s.%s(",GetCurrentThreadId(),dll->name,fun->name);
    else DPRINTF("%04x:CALL %s.%d(",GetCurrentThreadId(),dll->name,dll->ordbase+ordinal);
    if (fun->nrofargs>0) {
@@ -967,6 +981,8 @@ void WINAPI __regs_SNOOP_Return( CONTEXT *context )
    if (ret->dll->funs[ret->ordinal].nrofargs<0)
    	ret->dll->funs[ret->ordinal].nrofargs=(context->Esp - ret->origESP-4)/4;
    context->Eip = (DWORD)ret->origreturn;
+	if (TRACE_ON(timestamp))
+		print_timestamp();
    if (ret->args) {
    	int	i,max;