How to read +timestamp,+relay value?

[macchinetta]

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.714Call" and "8668.717Ret", 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.

Thank you.

[spoon0042]

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]

Thanks. Assuming we're right and those 3 ms are too long and causing an fps drop which I'm trying to debug 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]

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]

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]

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.