Community
Participate
Working Groups
We're running into an issue with TPTP displaying negative time. What's bizarre is that a) This is _not_ a distributed scenario. All the data is generated from one machine. b) The negative time only appears when we do a file import (after having profiled to file), NOT when we collect the data "live". Sent Marius a trace file that causes the negative time to appear when it's imported.
Rob, please attach the trace file to the defect
Created attachment 32467 [details] trcxml that causes negative time to appear
See also bug # 123628. I see the negative time when I use the "full" import but not the "compressed" import.
Upping to blocker since this defect is an absolute must fix in tptp 4.2.
Hi Rob, Can you provide some details on what has changed that prompted you to upgrade this defect from "normal" to "blocker", please? Thanks, Ruth.
We discovered after initially opening the defect that negative time not only appears when profiling to file and then doing an import, but it also appears on occasion when doing 'live' profiling. Given that negative time implies that there is something seriously wrong with the code that TPTP uses for calculating the method timings, and that we don't want to ship our product with the possibility of the user seeing method timings that are completely wrong, we thought we should raise this to blocker to ensure that the problem is fixed in the 4.2 release of TPTP.
Rob, would it be possible for you to send me a copy of the program so that I can profile it on my machine and see if the profiling file that I get has the same problem? I want to eliminate the possibility that there's some environment issue.
Responded with details in email.
The trace file is constructed incorrectly. The InvocationContext is supposed to be used only between traces, not within the same trace. You can see that the attached trcxml file is constructed incorrectly because there is at least one method (ticket="8499135027028111448") that is at stack depth 2 that is calling another method that is at stack depth 1.
Reopening as per our meeting. Workaround needs to be checked in for 4.2 and Ashish will be opening an enhancement for 4.3 for a more permanent solution.
As per discussion with Rob, reducing from 'blocking' to 'major' for 4.2 because Rob needs this fix post-4.2.
Moving to 4.2.1 because that's the version that the originator needs the fix in.
Ruth, Can you attach the patch to this defect? Thanks.
Created attachment 46053 [details] Patch as figured out by Marius The previous patch had been made on the 0520 version of TPTP, so I checked out the HEAD version, re-made the patch and tested it. It works as before. That said, while working on the fix for bugzilla #123628, I saw a condition that is legal yet the 119991 patch would treat as illegal. That is, 119991 looks at every intermediate delta time calculated and if it's negative sets the delta to 0. During 123628 I saw a case where an intermediate negative time was legal because the overhead of the child method was larger than the (end time of parent method - end time of child method). Because part of the time calculation was negative the correct result was reported rather than a result that was too large. Thus, rather than proposing this patch be applied as-is, I am going to create another workspace and put the fix for both bugzilla #119991 and bugzilla #123628 and see if a regression occurs. If it does then the patch for 119991 will have to be adjusted and retested by Ashish/Rob.
An update... The patch that Marius figured out should not be put in at all because it breaks/causes a regression in the time calculation of a basic test case. I've been looking to see if there's another way to satisfy 119991 that doesn't break an existing test case. Rob/Ashish had suggested looking to see if the InvocationContext is within the same agent - I'll look and see if that's possible. (Marius' fix was slightly different - it looked at the process rather than the agent and InvocationContext.) Background: The basic test imports a profiling file in full data and in execution statistics mode. The base time etc., despite the different algorithms for each mode, is supposed to be the same for both modes when the import completes. However, when the patch for 119991 is applied, the full data time is completely wrong and the execution statistics is slightly wrong. By removing the "if(deltaTime < 0)" if statements that I expressed concern about in comment #14, the execution statistics time returns to normal, the 119991 negative time problem is resolved, but the full data time remains completely wrong.
After investigating, it looks like there's no way to retrieve the InvocationContext for a particular TRCFullMethodInvocation. That's probably why Marius chose to make a patch by looking at the process & location on the stack. At this point the only hack that I can think of is to check if the size of the children's cumulative time is greater than the size of the invoking method's cumulative time, and if so to not factor the children's cumulative time into the equation. While this 'negative' test should not be done in the execution statistics import mode, it should be safe in full data mode because all of the calculation for a particular call is done at the same time in the one method. I've made a quick patch with this fix and it does not cause a regression in the simple test case that was regressed before. Attaching that patch to this defect. That said, there are some limitations of this patch. Because I can't think of anything that I can do to prevent negative times in the execution statistics mode, it's possible that you will see negative time when that type of import is used. I've also noticed an intermittent defect that happens around half the time when the attached trcxml file is imported: the base, cumulative etc. times for the package are smaller than the times of the profiled class. I have not seen this problem when importing the simple test case. At this point I don't know if the problem is because this is a specialized trace file or if it's more generic and just easier to trigger with this particular trace.
Created attachment 46267 [details] Patch as described in the previous comment.
Created attachment 46477 [details] The final patch that was checked in.
Fix checked in.
Closing.
