[DISCUSS] Optimize Tracing

[lmh <li...@foxmail.com>]

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:

​1. 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