[PHOENIX-2178] Tracing - total time listed for a certain trace does not correlate with query wall clock time

• Type: Sub-task
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 4.5.0
• Labels: gsoc2016 tracing
• Assignee: Unassigned
• Reporter: Mujtaba Chohan
• Created: 13/Aug/15 00:17
• Updated: 16/Jun/16 15:38

Description

Wall clock for a count * takes over a large table takes 30000+ms however total sum(end_time - start_time) is less than 250ms for trace_id generated for this count * query.

Output of trace table:

select sum(end_time  - start_time),count(*), description from SYSTEM.TRACING_STATS WHERE TRACE_ID=X group by description;
+------------------------------------------+------------------------------------------+------------------------------------------+
|       SUM((END_TIME - START_TIME))       |                 COUNT(1)                 |               DESCRIPTION                |
+------------------------------------------+------------------------------------------+------------------------------------------+
| 0                                        | 3                                        | ClientService.Scan                       |
| 240                                      | 253879                                   | HFileReaderV2.readBlock                  |
| 1                                        | 1                                        | Scanner opened on server                 |
+------------------------------------------+------------------------------------------+------------------------------------------+

Issue Links

• is related to: HTRACE-376 HTrace should support nanosecond time granularities