Re: indented relay traces

[Molle Bestefich]

James Hawkins wrote:

I don't know if you've ever wished the relay traces were indented by
the level of the call, so you can get a better feel for who calls what
from where, but I thought it would be nifty.  I've attached a patch
> for dlls/ntdll/relay.c that gives you this.


Hah, funny..
I made a patch to accomplish exactly the same a year ago.

Eric Pouech wrote:

this won't work for a multithreaded program


Mine did :-).
Also, it could filter calls beyond a specific level, as a way of
limiting output.


tools/examine_relay does what you want, plus some other goodies
(calls that didn't return...)
IMO it's better to instrument the tools after the relay trace,
rather than tweaking the trace generation for any potential goodie


IMHO, tools/examine_relay seemed to behave wrongly in some cases and
is also an overly complex solution compared to just doing this at
runtime.  It really doesn't take much code.

Re: indented relay traces

[Duane Clark]

James Hawkins wrote:

On 6/24/06, Eric Pouech <[EMAIL PROTECTED]> wrote:

this won't work for a multithreaded program
tools/examine_relay does what you want, plus some other goodies (calls
that didn't return...)


Ah, didn't know about that tool.  You learn something new every day.



It is also not immediately obvious that it will indent in two slightly 
different formats. Add a flag to the end of the command line to get 
different formatting:

tools/examine_relay wine.log -f

Re: indented relay traces

[Mike Hearn]

On Sat, 24 Jun 2006 02:15:09 -0700, James Hawkins wrote:
> Ah, didn't know about that tool.  You learn something new every day.

Perhaps it should be mentioned in the developer quickstart.

thanks -mike

Re: indented relay traces

[Jaap Stolk]

On 6/24/06, James Hawkins <[EMAIL PROTECTED]> wrote:

Ah, didn't know about that tool.  You learn something new every day.


didn't know about that tool too. sounds interesting.

usually I do something like:

// reduce log size:
egrep -v 
'RtlFreeHeap|RtlAllocateHeap|trace:syslevel:_Enter|trace:syslevel:_Leave|Ret
kernel32.MultiByteToWideChar|Ret  ntdll.RtlUpperChar'  all.txt >
all2.txt

// add line numbering: (to back-trace interesting things) all2.txt > all.txt
grep -n ''

// filter out interesting things: (manually add more interesting finds later)
egrep ':loaddll:|:ntoskrnl:|:warn:|Unable to|fixme' all.txt >
all_interesting.txt

Jaap.

Re: indented relay traces

[James Hawkins]

On 6/24/06, Eric Pouech <[EMAIL PROTECTED]> wrote:

>
this won't work for a multithreaded program
tools/examine_relay does what you want, plus some other goodies (calls
that didn't return...)


Ah, didn't know about that tool.  You learn something new every day.


IMO it's better to instrument the tools after the relay trace, rather
than tweaking the trace generation for any potential goodie



It's ok, I know it was a hack :)

--
James Hawkins

Re: indented relay traces

[Eric Pouech]

James Hawkins wrote:


Hey guys,

I don't know if you've ever wished the relay traces were indented by
the level of the call, so you can get a better feel for who calls what
from where, but I thought it would be nifty.  I've attached a patch
for dlls/ntdll/relay.c that gives you this.  You see the call level
next to the thread id, then twice that number of spaces, then the
usual relay information.  I'd paste an example, but it would just get
line wrapped, so patch your tree and give it a shot!


this won't work for a multithreaded program
tools/examine_relay does what you want, plus some other goodies (calls 
that didn't return...)
IMO it's better to instrument the tools after the relay trace, rather 
than tweaking the trace generation for any potential goodie


A+

indented relay traces

[James Hawkins]

Hey guys,

I don't know if you've ever wished the relay traces were indented by
the level of the call, so you can get a better feel for who calls what
from where, but I thought it would be nifty.  I've attached a patch
for dlls/ntdll/relay.c that gives you this.  You see the call level
next to the thread id, then twice that number of spaces, then the
usual relay information.  I'd paste an example, but it would just get
line wrapped, so patch your tree and give it a shot!

--
James Hawkins
diff --git a/dlls/ntdll/relay.c b/dlls/ntdll/relay.c
index b9f5cc0..2e9ab58 100644
--- a/dlls/ntdll/relay.c
+++ b/dlls/ntdll/relay.c
@@ -338,6 +338,8 @@ static inline void RELAY_PrintArgs( int 
 }
 }
 
+static int level = 0;
+
 extern LONGLONG call_entry_point( void *func, int nb_args, const int *args );
 __ASM_GLOBAL_FUNC( call_entry_point,
"\tpushl %ebp\n"
@@ -375,24 +377,28 @@ static LONGLONG WINAPI relay_call_from_3
 BYTE flags   = HIBYTE(HIWORD(idx));
 struct relay_private_data *data = descr->private;
 struct relay_entry_point *entry_point = data->entry_points + ordinal;
+char spaces[100];
 
 if (!TRACE_ON(relay))
 ret = call_entry_point( entry_point->orig_func, nb_args, stack + 1 );
 else
 {
+memset(spaces, ' ', level * 2);
+spaces[level * 2] = '\0';
+
 if (entry_point->name)
-DPRINTF( "%04lx:Call %s.%s(", GetCurrentThreadId(), data->dllname, entry_point->name );
+DPRINTF( "%04lx:%i:%sCall %s.%s(", GetCurrentThreadId(), level++, spaces, data->dllname, entry_point->name );
 else
-DPRINTF( "%04lx:Call %s.%u(", GetCurrentThreadId(), data->dllname, data->base + ordinal );
+DPRINTF( "%04lx:%i:%sCall %s.%u(", GetCurrentThreadId(), level++, spaces, data->dllname, data->base + ordinal );
 RELAY_PrintArgs( stack + 1, nb_args, descr->arg_types[ordinal] );
 DPRINTF( ") ret=%08x\n", stack[0] );
 
 ret = call_entry_point( entry_point->orig_func, nb_args, stack + 1 );
 
 if (entry_point->name)
-DPRINTF( "%04lx:Ret  %s.%s()", GetCurrentThreadId(), data->dllname, entry_point->name );
+DPRINTF( "%04lx:%i:%sRet  %s.%s()", GetCurrentThreadId(), --level, spaces, data->dllname, entry_point->name );
 else
-DPRINTF( "%04lx:Ret  %s.%u()", GetCurrentThreadId(), data->dllname, data->base + ordinal );
+DPRINTF( "%04lx:%i:%sRet  %s.%u()", GetCurrentThreadId(), --level, spaces, data->dllname, data->base + ordinal );
 
 if (flags & 1)  /* 64-bit return value */
 DPRINTF( " retval=%08x%08x ret=%08x\n",
@@ -419,6 +425,7 @@ void WINAPI __regs_relay_call_from_32_re
 BYTE *orig_func = entry_point->orig_func;
 int *args = (int *)context->Esp;
 int args_copy[32];
+char spaces[100];
 
 /* restore the context to what it was before the relay thunk */
 context->Eax = orig_eax;
@@ -428,10 +435,13 @@ void WINAPI __regs_relay_call_from_32_re
 
 if (TRACE_ON(relay))
 {
+memset(spaces, ' ', level * 2);
+spaces[level * 2] = '\0';
+
 if (entry_point->name)
-DPRINTF( "%04lx:Call %s.%s(", GetCurrentThreadId(), data->dllname, entry_point->name );
+DPRINTF( "%04lx:%i:%sCall %s.%s(", GetCurrentThreadId(), level++, spaces, data->dllname, entry_point->name );
 else
-DPRINTF( "%04lx:Call %s.%u(", GetCurrentThreadId(), data->dllname, data->base + ordinal );
+DPRINTF( "%04lx:%i:%sCall %s.%u(", GetCurrentThreadId(), level++, spaces, data->dllname, data->base + ordinal );
 RELAY_PrintArgs( args, nb_args, descr->arg_types[ordinal] );
 DPRINTF( ") ret=%08x\n", ret_addr );
 
@@ -456,12 +466,12 @@ void WINAPI __regs_relay_call_from_32_re
 if (TRACE_ON(relay))
 {
 if (entry_point->name)
-DPRINTF( "%04lx:Ret  %s.%s() retval=%08lx ret=%08lx\n",
- GetCurrentThreadId(), data->dllname, entry_point->name,
+DPRINTF( "%04lx:%i:%sRet  %s.%s() retval=%08lx ret=%08lx\n",
+ GetCurrentThreadId(), --level, spaces, data->dllname, entry_point->name,
  context->Eax, context->Eip );
 else
-DPRINTF( "%04lx:Ret  %s.%u() retval=%08lx ret=%08lx\n",
- GetCurrentThreadId(), data->dllname, data->base + ordinal,
+DPRINTF( "%04lx:%i:%sRet  %s.%u() retval=%08lx ret=%08lx\n",
+ GetCurrentThreadId(), --level, spaces, data->dllname, data->base + ordinal,
  context->Eax, context->Eip );
 DPRINTF( "%04lx:  eax=%08lx ebx=%08lx ecx=%08lx edx=%08lx esi=%08lx edi=%08lx "
  "ebp=%08lx esp=%08lx ds=%04lx es=%04lx fs=%04lx gs=%04lx flags=%08lx\n",