tid, another attempt

Francois Gouget fgouget at free.fr
Sun May 6 22:42:36 CDT 2001


   No 'notid' hack this time. tids are printed on every line if you
specify either +relay, +snoop or +tid. The tid is printed in the first
column in a fixed format which makes it easy to see which thread is
doing what. Here an extract of a multi-thread demo from the Petzold 95.


089b2038:trace:gdi:GDI_FreeObject (09c6): leave 1
089b2038:trace:win:X11DRV_SetWindowPos 	status flags = 0004
081df9f0:trace:event:EVENT_ProcessEvent returns.
081df9f0:trace:event:EVENT_ProcessEvent called.
081df9f0:trace:event:EVENT_ProcessEvent Got event MotionNotify for hwnd 0138
089b2038:trace:class:GetClassWord 330 ffffffe0
089b2038:trace:atom:ATOM_GetAtomNameA (global) c00c -> "Fille3"
089b2038:trace:relay:WINPROC_CallWndProc(wndproc=0x4015db,hwnd=00000330,msg=WM_WINDOWPOSCHANGED,wp=00000000,lp=405a6adc)
081df9f0:trace:cursor:X11DRV_SendEvent (8001,1116,153)
081df9f0:trace:event:EVENT_ProcessEvent returns.
081df9f0:trace:event:EVENT_ProcessEvent called.
081df9f0:trace:event:EVENT_ProcessEvent Got event MotionNotify for hwnd 0138
081df9f0:trace:cursor:X11DRV_SendEvent (8001,1118,145)
089b2038:Call user32.DefWindowProcA(00000330,00000047,00000000,405a6adc) ret=00401691
089b2038:trace:class:GetClassWord 330 ffffffe0
089b2038:trace:atom:ATOM_GetAtomNameA (global) c00c -> "Fille3"
089b2038:trace:relay:WINPROC_CallWndProc(wndproc=0x4015db,hwnd=00000330,msg=WM_MOVE,wp=00000000,lp=01b40001)
089b2038:Call user32.DefWindowProcA(00000330,00000003,00000000,01b40001) ret=00401691
089b2038:Ret  user32.DefWindowProcA() retval=00000000 ret=00401691
089b2038:trace:relay:WINPROC_CallWndProc(wndproc=0x4015db,hwnd=00000330,msg=WM_MOVE,wp=00000000,lp=01b40001) retval=00000000
089b2038:trace:class:GetClassWord 330 ffffffe0
089b2038:trace:atom:ATOM_GetAtomNameA (global) c00c -> "Fille3"
089b2038:trace:class:GetClassWord 330 ffffffe0
089b2038:trace:atom:ATOM_GetAtomNameA (global) c00c -> "Fille3"
089b2038:trace:relay:WINPROC_CallWndProc(wndproc=0x4015db,hwnd=00000330,msg=WM_SIZE,wp=00000000,lp=01b10251)
089b2038:trace:relay:WINPROC_CallWndProc(wndproc=0x4015db,hwnd=00000330,msg=WM_SIZE,wp=00000000,lp=01b10251) retval=00000000
089b2038:trace:class:GetClassWord 330 ffffffe0
089b2038:trace:atom:ATOM_GetAtomNameA (global) c00c -> "Fille3"
089b2038:Re`t  user32.DefWindowProcA() retval=00000000 ret=00401691


   This reduces the changes made to the relay and snoop code to just
printing the pid in the first column instead of the last. Only
debugtools.c which implements TRACE & co has to know about
+tid (and relay/snoop).


 Changelog:

 * dlls/ntdll/ntdll.spec,
   dlls/ntdll/debugtools.c,
   if1632/relay.c,
   relay32/relay386.c,
   relay32/snoop.c

   Print the tid in the first column when either relay, snoop or tid is
specified



   (In if1632/relay.c, renamed some CallTo16 to RetFrom16, correct?)


--
Francois Gouget         fgouget at free.fr        http://fgouget.free.fr/
                               {free} || die "";
-------------- next part --------------
Index: dlls/ntdll/ntdll.spec
===================================================================
RCS file: /home/wine/wine/dlls/ntdll/ntdll.spec,v
retrieving revision 1.45
diff -u -r1.45 ntdll.spec
--- dlls/ntdll/ntdll.spec	2001/04/16 20:24:47	1.45
+++ dlls/ntdll/ntdll.spec	2001/05/07 01:47:30
@@ -5,7 +5,7 @@
                 file fixup global heap int int10 int16 int17 int19 int21 int31
                 io loaddll local module ntdll process profile reg relay resource
                 segment seh selector server snoop string system tape task thread
-                thunk timer toolhelp ver virtual vxd win32)
+                thunk tid timer toolhelp ver virtual vxd win32)
 
 #note that the Zw... functions are alternate names for the 
 #Nt... functions.  (see www.sysinternals.com for details)
Index: dlls/ntdll/debugtools.c
===================================================================
RCS file: /home/cvs/wine/wine/dlls/ntdll/debugtools.c,v
retrieving revision 1.6
diff -u -r1.6 debugtools.c
--- dlls/ntdll/debugtools.c	2001/03/21 23:54:59	1.6
+++ dlls/ntdll/debugtools.c	2001/05/07 03:09:56
@@ -15,6 +15,11 @@
 #include "winnt.h"
 #include "wtypes.h"
 
+DECLARE_DEBUG_CHANNEL(relay);
+DECLARE_DEBUG_CHANNEL(snoop);
+DECLARE_DEBUG_CHANNEL(tid);
+
+
 /* ---------------------------------------------------------------------- */
 
 struct debug_info
@@ -248,8 +253,11 @@
     int ret = 0;
 
     va_start(valist, format);
-    if (cls < __DBCL_COUNT)
-        ret = wine_dbg_printf( "%s:%s:%s ", classes[cls], channel + 1, function );
+    if (cls < __DBCL_COUNT) {
+        if (TRACE_ON(relay) || TRACE_ON(snoop) || TRACE_ON(tid))
+            ret = wine_dbg_printf( "%08lx:", GetCurrentThreadId() );
+        ret += wine_dbg_printf( "%s:%s:%s ", classes[cls], channel + 1, function );
+    }
     if (format)
         ret += wine_dbg_vprintf( format, valist );
     va_end(valist);
Index: if1632/relay.c
===================================================================
RCS file: /home/cvs/wine/wine/if1632/relay.c,v
retrieving revision 1.41
diff -u -r1.41 relay.c
--- if1632/relay.c	2001/02/14 23:11:19	1.41
+++ if1632/relay.c	2001/05/07 03:10:01
@@ -154,7 +154,7 @@
     args = BUILTIN_GetEntryPoint16( frame, funstr, &ordinal );
     if (!args) return; /* happens for the two snoop register relays */
     if (!RELAY_ShowDebugmsgRelay(funstr)) return;
-    DPRINTF( "Call %s(",funstr);
+    DPRINTF( "%08lx:Call %s(",GetCurrentThreadId(),funstr);
     VA_START16( args16 );
 
     usecdecl = ( *args == 'c' );
@@ -274,7 +274,7 @@
     args = BUILTIN_GetEntryPoint16( frame, funstr, &ordinal );
     if (!args) return;
     if (!RELAY_ShowDebugmsgRelay(funstr)) return;
-    DPRINTF( "Ret  %s() ",funstr);
+    DPRINTF( "%08lx:Ret  %s() ",GetCurrentThreadId(),funstr);
 
     if ( memcmp( args+2, "long_", 5 ) == 0 )
     {
@@ -324,7 +324,8 @@
     {
         CONTEXT86 *context = (CONTEXT86 *)target;
 
-        DPRINTF("CallTo16(func=%04lx:%04x,ds=%04lx",
+        DPRINTF("%08lx:CallTo16(func=%04lx:%04x,ds=%04lx",
+                GetCurrentThreadId(),
                 context->SegCs, LOWORD(context->Eip), context->SegDs );
         while (nb_args--) DPRINTF( ",0x%04x", *--stack16 );
         DPRINTF(") ss:sp=%04x:%04x\n", SELECTOROF(teb->cur_stack),
@@ -336,7 +337,8 @@
     }
     else
     {
-        DPRINTF("CallTo16(func=%04x:%04x,ds=%04x",
+        DPRINTF("%08lx:CallTo16(func=%04x:%04x,ds=%04x",
+                GetCurrentThreadId(),
                 HIWORD(target), LOWORD(target), SELECTOROF(teb->cur_stack) );
         while (nb_args--) DPRINTF( ",0x%04x", *--stack16 );
         DPRINTF(") ss:sp=%04x:%04x\n", SELECTOROF(teb->cur_stack),
@@ -356,7 +358,8 @@
 
     if (!reg_func)
     {
-        DPRINTF("CallTo16() ss:sp=%04x:%04x retval=0x%08x\n", 
+        DPRINTF("%08lx:RetFrom16() ss:sp=%04x:%04x retval=0x%08x\n",
+                GetCurrentThreadId(),
                 SELECTOROF(NtCurrentTeb()->cur_stack),
                 OFFSETOF(NtCurrentTeb()->cur_stack), ret_val);
     }
@@ -364,7 +367,8 @@
     {
         CONTEXT86 *context = (CONTEXT86 *)ret_val;
 
-        DPRINTF("CallTo16() ss:sp=%04x:%04x\n", 
+        DPRINTF("%08lx:RetFrom16() ss:sp=%04x:%04x\n",
+                GetCurrentThreadId(),
                 SELECTOROF(NtCurrentTeb()->cur_stack),
                 OFFSETOF(NtCurrentTeb()->cur_stack));
         DPRINTF("     AX=%04x BX=%04x CX=%04x DX=%04x BP=%04x SP=%04x\n",
Index: relay32/relay386.c
===================================================================
RCS file: /home/cvs/wine/wine/relay32/relay386.c,v
retrieving revision 1.34
diff -u -r1.34 relay386.c
--- relay32/relay386.c	2001/04/24 23:17:10	1.34
+++ relay32/relay386.c	2001/05/07 03:10:05
@@ -182,9 +182,9 @@
 
     get_entry_point( buffer, relay );
 
-    DPRINTF( "Call %s(", buffer );
+    DPRINTF( "%08lx:Call %s(", GetCurrentThreadId(), buffer );
     RELAY_PrintArgs( args, nb_args, relay->argtypes );
-    DPRINTF( ") ret=%08x tid=%08lx\n", ret_addr, GetCurrentThreadId() );
+    DPRINTF( ") ret=%08x\n", ret_addr );
     ret64 = (relay->argtypes & 0x80000000) && (nb_args < 16);
 
     if (relay->ret == 0xc3) /* cdecl */
@@ -274,11 +274,13 @@
         }
     }
     if (ret64)
-        DPRINTF( "Ret  %s() retval=%08x%08x ret=%08x tid=%08lx\n",
-                 buffer, (UINT)(ret >> 32), (UINT)ret, ret_addr, GetCurrentThreadId() );
+        DPRINTF( "%08lx:Ret  %s() retval=%08x%08x ret=%08x\n",
+                 GetCurrentThreadId(),
+                 buffer, (UINT)(ret >> 32), (UINT)ret, ret_addr );
     else
-        DPRINTF( "Ret  %s() retval=%08x ret=%08x tid=%08lx\n",
-                 buffer, (UINT)ret, ret_addr, GetCurrentThreadId() );
+        DPRINTF( "%08lx:Ret  %s() retval=%08x ret=%08x\n",
+                 GetCurrentThreadId(),
+                 buffer, (UINT)ret, ret_addr );
 
     return ret;
 }
@@ -320,7 +322,7 @@
 
     get_entry_point( buffer, relay );
 
-    DPRINTF( "Call %s(", buffer );
+    DPRINTF( "%08lx:Call %s(", GetCurrentThreadId(), buffer );
     RELAY_PrintArgs( args, nb_args, relay->argtypes );
     DPRINTF( ") ret=%08lx fs=%04lx\n", context->Eip, context->SegFs );
 
@@ -364,7 +366,8 @@
         assert(FALSE);
     }
 
-    DPRINTF( "Ret  %s() retval=%08lx ret=%08lx fs=%04lx\n",
+    DPRINTF( "%08lx:Ret  %s() retval=%08lx ret=%08lx fs=%04lx\n",
+             GetCurrentThreadId(),
              buffer, context->Eax, context->Eip, context->SegFs );
 
     DPRINTF(" eax=%08lx ebx=%08lx ecx=%08lx edx=%08lx esi=%08lx edi=%08lx\n",
Index: relay32/snoop.c
===================================================================
RCS file: /home/cvs/wine/wine/relay32/snoop.c,v
retrieving revision 1.40
diff -u -r1.40 snoop.c
--- relay32/snoop.c	2001/04/16 19:03:45	1.40
+++ relay32/snoop.c	2001/05/07 03:10:05
@@ -322,7 +328,7 @@
 
 	context->Eip = (DWORD)fun->origfun;
 
-	DPRINTF("CALL %s.%ld: %s(",dll->name,ordinal,fun->name);
+	DPRINTF("%08lx:CALL %s.%ld: %s(",GetCurrentThreadId(),dll->name,ordinal,fun->name);
 	if (fun->nrofargs>0) {
 		max = fun->nrofargs; if (max>16) max=16;
 		for (i=0;i<max;i++)
@@ -334,7 +340,7 @@
 		ret->args = HeapAlloc(GetProcessHeap(),0,16*sizeof(DWORD));
 		memcpy(ret->args,(LPBYTE)(context->Esp + 4),sizeof(DWORD)*16);
 	}
-	DPRINTF(") ret=%08lx tid=%08lx\n", (DWORD)ret->origreturn, GetCurrentThreadId());
+	DPRINTF(") ret=%08lx\n",(DWORD)ret->origreturn);
 }
 
 
@@ -353,18 +359,21 @@
 	if (ret->args) {
 		int	i,max;
 
-		DPRINTF("RET  %s.%ld: %s(",ret->dll->name,ret->ordinal,ret->dll->funs[ret->ordinal].name);
+		DPRINTF("%08lx:RET  %s.%ld: %s(",
+		        GetCurrentThreadId(),
+		        ret->dll->name,ret->ordinal,ret->dll->funs[ret->ordinal].name);
 		max = ret->dll->funs[ret->ordinal].nrofargs;
 		if (max>16) max=16;
 
 		for (i=0;i<max;i++)
 			DPRINTF("%s%s",SNOOP_PrintArg(ret->args[i]),(i<max-1)?",":"");
-		DPRINTF(") retval = %08lx ret=%08lx tid=%08lx\n",
-			context->Eax, (DWORD)ret->origreturn, GetCurrentThreadId());
+		DPRINTF(") retval = %08lx ret=%08lx\n",
+			context->Eax,(DWORD)ret->origreturn );
 		HeapFree(GetProcessHeap(),0,ret->args);
 		ret->args = NULL;
 	} else
-		DPRINTF("RET  %s.%ld: %s() retval = %08lx ret=%08lx tid=%08lx\n",
+		DPRINTF("%08lx:RET  %s.%ld: %s() retval = %08lx ret=%08lx tid=%08lx\n",
+			GetCurrentThreadId(),
 			ret->dll->name,ret->ordinal,ret->dll->funs[ret->ordinal].name,
 			context->Eax, (DWORD)ret->origreturn, GetCurrentThreadId());
 	ret->origreturn = NULL; /* mark as empty */


More information about the wine-patches mailing list