[IMPALA-10235] Averaged timer profile counters can be negative for trivial queries

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Fix Version/s: Impala 4.0.0
• Labels: newbie ramp-up
• Epic Color: ghx-label-10
• Assignee: Tim Armstrong
• Reporter: Sahil Takiar
• Created: 13/Oct/20 18:17
• Updated: 04/Dec/20 18:00
• Resolved: 04/Dec/20 18:00

Description

Steps to reproduce on master:

stakiar @ stakiar-desktop -bash ~/Impala 2020-10-13 11:13:02 master
 [74] → ./bin/impala-shell.sh -q "select sleep(100) from functional.alltypes limit 25" -p > profile-output.txt
...
Query: select sleep(100) from functional.alltypes limit 25
Query submitted at: 2020-10-13 11:13:07 (Coordinator: http://stakiar-desktop:25000)
Query progress can be monitored at: http://stakiar-desktop:25000/query_plan?query_id=694f94671571d4d1:cdec9db900000000
Fetched 25 row(s) in 2.64s

Attached the contents of profile-output.txt

Relevant portion of the profile:

    Averaged Fragment F00:(Total: 2s603ms, non-child: 272.519us, % non-child: 0.01%)
...
       - CompletionTime: -1665218428.000ns
...
       - TotalThreadsTotalWallClockTime: -1686005515.000ns
         - TotalThreadsSysTime: 0.000ns
         - TotalThreadsUserTime: 2.151ms
...
       - TotalTime: -1691524485.000ns

For whatever reason, this only affects the averaged fragment profile. For this query, there was only one coordinator fragment and thus only one fragment instance. The coordinator fragment instance showed normal timer values:

    Coordinator Fragment F00:
...
         - CompletionTime: 2s629ms
...
         - TotalThreadsTotalWallClockTime: 2s608ms
           - TotalThreadsSysTime: 0.000ns
           - TotalThreadsUserTime: 2.151ms
...
         - TotalTime: 2s603ms