tracing
on"],[20,"\n","24:\"Dkuu\"|36:177"],[20,"Msg:
The statement is executed
successfully."],[20,"\n","24:\"qwxW\"|36:177"],[20,"Execute
statement. The information about the traced statement is captured and
displayed.","31:2"],[20,"\n","24:\"fWBF\"|list-id:\"fQDf\"|list-start:\"2\"|ordered:\"decimal\""],[20,"IoTDB>
select s1 from
root.sg1.d1"],[20,"\n","24:\"Fux4\"|36:177"],[20,"+-----------------------------+--------------+"],[20,"\n","24:\"PsaQ\"|36:177"],[20,"|
Time|root.sg1.d1.s1|"],[20,"\n","24:\"fXrY\"|36:177"],[20,"+-----------------------------+--------------+"],[20,"\n","24:\"Qskk\"|36:177"],[20,"|1970-01-01T08:00:00.000+08:00|
1|"],[20,"\n","24:\"BNl8\"|36:177"],[20,"|1970-01-01T08:00:00.001+08:00|
1|"],[20,"\n","24:\"lVYM\"|36:177"],[20,"|1970-01-01T08:00:00.002+08:00|
1|"],[20,"\n","24:\"xPVi\"|36:177"],[20,"|1970-01-01T08:00:00.003+08:00|
1|"],[20,"\n","24:\"NIfT\"|36:177"],[20,"|1970-01-01T08:00:00.004+08:00|
1|"],[20,"\n","24:\"2w6G\"|36:177"],[20,"|1970-01-01T08:00:00.005+08:00|
1|"],[20,"\n","24:\"L5Vw\"|36:177"],[20,"|1970-01-01T08:00:00.006+08:00|
1|"],[20,"\n","24:\"Gk7p\"|36:177"],[20,"|1970-01-01T08:00:00.007+08:00|
1|"],[20,"\n","24:\"phPi\"|36:177"],[20,"|1970-01-01T08:00:00.008+08:00|
1|"],[20,"\n","24:\"EeIn\"|36:177"],[20,"|1970-01-01T08:00:00.009+08:00|
1|"],[20,"\n","24:\"9pDE\"|36:177"],[20,"+-----------------------------+--------------+"],[20,"\n","24:\"nvvb\"|36:177"],[20,"Total
line number =
10"],[20,"\n","24:\"7nhX\"|36:177"],[20,"It
costs
0.541s"],[20,"\n","24:\"An8l\"|36:177"],[20,"\n","24:\"oW1Q\"|36:177"],[20,"Tracing
- Session Id: 1, Query Id:
1"],[20,"\n","24:\"Wjau\"|36:177"],[20,"Tracing
- Statement: select s1 from
root.sg1.d1"],[20,"\n","24:\"4W25\"|36:177"],[20,"Tracing
activities:"],[20,"\n","24:\"AvYH\"|36:177"],[20,"+-----------------------+----------------------------------------------------+------------+"],[20,"\n","24:\"cElH\"|36:177"],[20,"|Timestamp
| Activity |Elapsed
Time|"],[20,"\n","24:\"LLhC\"|36:177"],[20,"+-----------------------+----------------------------------------------------+------------+"],[20,"\n","24:\"DIx6\"|36:177"],[20,"|2021-09-10
15:59:10.906| Execute Query Statement: select s1 from root.sg1.d1|0
|"],[20,"\n","24:\"pWcd\"|36:177"],[20,"|2021-09-10
15:59:10.929| Parsing SQL to Physical Plan |23
|"],[20,"\n","24:\"HHA7\"|36:177"],[20,"|2021-09-10
15:59:10.935| Preparing for creating QueryDataSet |29
|"],[20,"\n","24:\"yyNf\"|36:177"],[20,"|2021-09-10
15:59:10.936| Optimizing Expression |30
|"],[20,"\n","24:\"y8oT\"|36:177"],[20,"|2021-09-10
15:59:10.962| Initing Managed SeriesReader |56
|"],[20,"\n","24:\"BVmF\"|36:177"],[20,"|2021-09-10
15:59:11.342| Creating QueryDataSet |436
|"],[20,"\n","24:\"B48V\"|36:177"],[20,"|
| * Number of series paths: 1 |
|"],[20,"\n","24:\"xH5K\"|36:177"],[20,"|
| * Number of sequence files: 1 |
|"],[20,"\n","24:\"boOR\"|36:177"],[20,"|
| * Number of unsequence files: 0 |
|"],[20,"\n","24:\"MwfQ\"|36:177"],[20,"|
| * Number of chunks: 1, |
|"],[20,"\n","24:\"RGQP\"|36:177"],[20,"|
| Average data points of chunks: 10.0 |
|"],[20,"\n","24:\"CpX0\"|36:177"],[20,"|
| * Rate of overlapped pages: 0.0%, |
|"],[20,"\n","24:\"W2xW\"|36:177"],[20,"|
| 0 overlapped pages in total 1 pages. |
|"],[20,"\n","24:\"LTzZ\"|36:177"],[20,"|
| * Number of ReadTask: 1 |
|"],[20,"\n","24:\"ikWT\"|36:177"],[20,"|2021-09-10
15:59:11.364| Request complete |458
|"],[20,"\n","24:\"xocR\"|36:177"],[20,"+-----------------------+----------------------------------------------------+------------+"],[20,"\n","24:\"mnre\"|36:177"],[20,"Turn
off
tracing.","31:2"],[20,"\n","24:\"qtCe\"|list-id:\"rdOF\"|list-start:\"3\"|ordered:\"decimal\""],[20,"IoTDB>
tracing
off"],[20,"\n","24:\"TdDP\"|36:177"],[20,"Msg:
The statement is executed
successfully."],[20,"\n","24:\"VJGp\"|36:177"],[20,"\n","24:\"nhaa\""],[20,"What
do you think?
","31:2"],[20,"\n","24:\"kgNa\""],[20,"For
more details, please refer to:
"],[20,"https://issues.apache.org/jira/browse/IOTDB-1607","16:\"https%3A%2F%2Fissues.apache.org%2Fjira%2Fbrowse%2FIOTDB-1607\""],[20,"\n","24:\"5KGS\""],[20,"\n","24:\"zKw4\""],[20,"Best,","31:2"],[20,"\n","24:\"5uEv\""],[20,"-----------------------------------","31:2"],[20,"\n","24:\"Aejm\""],[20,"Minghui
Liu","31:2"],[20,"\n","24:\"C8ty\""],[20,"School
of Software, Tsinghua University","31:2"]]">
Hi,
To make tracing more useful for error reporting and discovering performance
bottlenecks, I will do the following works:
The configuration enable_performance_tracing will be removed. A session
can only trace statements which it executes; it cannot see a trace of another
session.
The information about traced statements will be displayed directly in CLI to
make it easier to see.
Each step of executing the statement will be captured and displayed. The
Tracing activities table contains each step's information about traced
statements. The table has these columns: Timestamp, Activity, and Elapsed Time.
A typical usage will be:
?6?71. Turn on tracing.
IoTDB> tracing on Msg: The statement is executed successfully.2. Execute
statement. The information about the traced statement is captured and
displayed.IoTDB> select s1 from root.sg1.d1
+-----------------------------+--------------+ |
Time|root.sg1.d1.s1| +-----------------------------+--------------+
|1970-01-01T08:00:00.000+08:00| 1| |1970-01-01T08:00:00.001+08:00|
1| |1970-01-01T08:00:00.002+08:00| 1|
|1970-01-01T08:00:00.003+08:00| 1| |1970-01-01T08:00:00.004+08:00|
1| |1970-01-01T08:00:00.005+08:00| 1|
|1970-01-01T08:00:00.006+08:00| 1| |1970-01-01T08:00:00.007+08:00|
1| |1970-01-01T08:00:00.008+08:00| 1|
|1970-01-01T08:00:00.009+08:00| 1|
+-----------------------------+--------------+ Total line number = 10 It costs
0.541s Tracing - Session Id: 1, Query Id: 1 Tracing - Statement: select s1 from
root.sg1.d1 Tracing activities:
+-----------------------+----------------------------------------------------+------------+
|Timestamp | Activity
|Elapsed Time|
+-----------------------+----------------------------------------------------+------------+
|2021-09-10 15:59:10.906| Execute Query Statement: select s1 from
root.sg1.d1|0 | |2021-09-10 15:59:10.929| Parsing SQL to Physical
Plan |23 | |2021-09-10 15:59:10.935| Preparing
for creating QueryDataSet |29 | |2021-09-10
15:59:10.936| Optimizing Expression |30 |
|2021-09-10 15:59:10.962| Initing Managed SeriesReader
|56 | |2021-09-10 15:59:11.342| Creating QueryDataSet
|436 | | | * Number of series paths:
1 | | | | * Number of
sequence files: 1 | | | |
* Number of unsequence files: 0 | | |
| * Number of chunks: 1, | | |
| Average data points of chunks: 10.0 |
| | | * Rate of overlapped pages: 0.0%,
| | | | 0 overlapped pages in total 1
pages. | | | | * Number of
ReadTask: 1 | | |2021-09-10 15:59:11.364|
Request complete |458 |
+-----------------------+----------------------------------------------------+------------+3.Turn
off tracing.IoTDB> tracing off Msg: The statement is executed successfully.
What do you think?
JIRA link: https://issues.apache.org/jira/browse/IOTDB-1607
Best,
-----------------------------------
Minghui Liu
School of Software, Tsinghua University
