[UIMA-941] No ProcessTrace events for process calls that take 0ms

• Type: Bug
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 2.2.2
• Fix Version/s: 2.3
• Component/s: Core Java Framework

Environment

Windows XP, Java 1.5

• Assignee: Unassigned
• Reporter: Thilo Goetz
• Created: 28/Mar/08 07:19
• Updated: 31/Aug/09 23:03
• Resolved: 31/Aug/09 23:03

Description

Found when testing release candidate 4 of 2.2.2. Here's the text of an email I wrote. Adam responded that it's probably a bug.

http://www.mail-archive.com/uima-dev%40incubator.apache.org/msg06565.html

I was just testing CVD for the next release, and tried
out the new performance report feature. Internally, this
uses the ProcessTrace feature of AnalysisEngine.process().
It seems that if the process() call returns very quickly,
i.e., in 0ms according to the Java timer, no ProcessTrace
sub-events are recorded. For example, I'm running the
tagger, and here's some output I get:

This one looks fine, as expected:

3/27/08 4:29:52 PM - 10: org.apache.uima.tools.cvd.MainFrame.internalRunAE(1570): INFO: Process trace of AE run:
Component Name: HmmTaggerTAE
Event Type: Analysis
Duration: 2078ms (100%)
Sub-events:
Component Name: WhitespaceTokenizer
Event Type: Analysis
Duration: 265ms (12.75%)

Component Name: Hidden Markov Model - Part of Speech Tagger
Event Type: Analysis
Duration: 1813ms (87.25%)

Component Name: Fixed Flow Controller
Event Type: Analysis
Duration: 0ms (0%)

Next one seems to have lost the tagger:

3/27/08 4:30:08 PM - 10: org.apache.uima.tools.cvd.MainFrame.internalRunAE(1570): INFO: Process trace of AE run:
Component Name: HmmTaggerTAE
Event Type: Analysis
Duration: 16ms (100%)
Sub-events:
Component Name: WhitespaceTokenizer
Event Type: Analysis
Duration: 16ms (100%)

Component Name: Fixed Flow Controller
Event Type: Analysis
Duration: 0ms (0%)

Finally, this one only has the flow controller:

3/27/08 4:30:19 PM - 10: org.apache.uima.tools.cvd.MainFrame.internalRunAE(1570): INFO: Process trace of AE run:
Component Name: HmmTaggerTAE
Event Type: Analysis
Duration: 0ms
Sub-events:
Component Name: Fixed Flow Controller
Event Type: Analysis
Duration: 0ms

Looking at this in the debugger, there are no subevents
there, so it's not a problem with the printing.

Is this expected, or is it a bug? Seems to me it is a bug,
but I'm not sure from the documentation.

--Thilo