How to read +timestamp,+relay value?

Open forum for end-user questions about Wine. Before asking questions, check out the Wiki as a first step.
Forum Rules
Post Reply
macchinetta
Level 4
Level 4
Posts: 111
Joined: Sat Jan 31, 2015 3:03 pm
Location: Italy

How to read +timestamp,+relay value?

Post by macchinetta » Wed Feb 17, 2021 10:59 am

Hi. I've some question about debugging in wine that I haven't found answers in the wiki.

First question: If I use timestamp in debugging performance to understand what use CPU time or take too long time to run, what timestamp tell to me?

For example if I see "8668.714:0200:Call" and "8668.717:0200:Ret", what is exactly 8668 and 714/718? And what is considered a too long time in terms of performance?

Second question: how +relay consider exactly 'Call' and 'Ret'? If I use +relay in combination with timestamp, what should I have to search exactly in the log to understand where is the problem?

Combining the two question: If there is different timestamp value (assuming this indicate a too long time) between Call and Ret of the same function, what can be mean this?

If you think this last one is a stupid question consider that I've try to add custom ERR at the beginning and at the end of the function and difference in timestamp of that error seems beetween function end and next call while call and return has same timestamp, and it's the same for the parent functions, at least as long as I've been able to find them. :roll: :D

Thank you.

spoon0042
Level 6
Level 6
Posts: 519
Joined: Thu Dec 24, 2009 11:00 am

Re: How to read +timestamp,+relay value?

Post by spoon0042 » Wed Feb 17, 2021 9:17 pm

timestamp is easy enough, it's your system's uptime in seconds and milliseconds. So your example call presumably took 3 ms.

On a modern PC if you notice it it might be too long I guess? :)

Beyond that I'm not sure. I don't quite understand what you mean, an example might help.

macchinetta
Level 4
Level 4
Posts: 111
Joined: Sat Jan 31, 2015 3:03 pm
Location: Italy

Re: How to read +timestamp,+relay value?

Post by macchinetta » Thu Feb 18, 2021 10:37 am

Thanks. Assuming we're right and those 3 ms are too long and causing an fps drop which I'm trying to debug :D an for example I see this:

Code: Select all

8668.714:0200:Call wined3d.wined3d_swapchain_present(13eb1c60,00000000,00000000,00000000,00000000,00000000) ret=67c957ee
... other relay output ...
8668.717:0200:Ret  wined3d.wined3d_swapchain_present() retval=00000000 ret=67c957ee
My question is: How it should means? And where should I look in the code to investigate for the cause of the slowdown?

At first I thought it means a problem during function execution so I try to insert some custom error in the source in order to get timestamps of the parts of the function body, but I get an output like this:

Code: Select all

8668.714:0200:Err:wined3d:wined3d_swapchain_present starting function
8668.714:0200:Err:wined3d:wined3d_swapchain_present ending function
8668.718:0200:Err:wined3d:wined3d_swapchain_present starting function
8668.718:0200:Err:wined3d:wined3d_swapchain_present ending function
8668.721:0200:Err:wined3d:wined3d_swapchain_present starting function
8668.721:0200:Err:wined3d:wined3d_swapchain_present ending function
So I repeat the trick with the parent functions until I found a function that is never call in any part of the source :?: and that function has same timestamp as above.

What am I ignoring? Does it have to do with other relay output? Or simply +Relay can fake timestamp?

I would like to find an answer to these questions before consuming time.

spoon0042
Level 6
Level 6
Posts: 519
Joined: Thu Dec 24, 2009 11:00 am

Re: How to read +timestamp,+relay value?

Post by spoon0042 » Fri Feb 26, 2021 5:44 pm

I guess it's possible it only updates the timestamp when the function is called, or something like that. You could try putting an explicit sleep somewhere to verify?

Also there was a bug recently causing pauses, I don't know if your problem was new or not but that bug should be fixed.

macchinetta
Level 4
Level 4
Posts: 111
Joined: Sat Jan 31, 2015 3:03 pm
Location: Italy

Re: How to read +timestamp,+relay value?

Post by macchinetta » Sun Feb 28, 2021 1:38 pm

For the moment I prefer wait for someone knows the answers before wasting any time.

Reading the entries in appdb the bug seem present at least from wine 1.6 (too old to be run on updated system), so I guess it insn't related with bug you say.

If you're curious see bug 50093 for a summary.

spoon0042
Level 6
Level 6
Posts: 519
Joined: Thu Dec 24, 2009 11:00 am

Re: How to read +timestamp,+relay value?

Post by spoon0042 » Mon Mar 01, 2021 2:32 pm

Ah, I see. Yeah I don't think I'd be much help, especially since the bug report indicates it may be nvidia specific. Good luck I guess. :)

Post Reply