[Bug]: In the longrunning tests, some query response times were exceptionally long.

Is there an existing issue for the same bug?

[X] I have checked the existing issues.

Environment

- Version or commit-id (e.g. v0.1.0 or 8b23a93): 0b1c9988
- Hardware parameters:
- OS type:
- Others:

Actual Behavior

During long-running tests, it was found that the same query occasionally takes an exceptionally long time to execute once or twice, and the time recorded in the exec_plan is vastly different from the actual query time. This issue is illustrated by the example of TPCH q2, which normally takes less than 10 seconds but took 60 seconds in this case.

However, the execution time recorded in exec_plan is "Time": [{"name": "Time Consumed", "unit": "ns", "value": 229236854}, {"name": "Wait Time", "unit": "ns", "value": 1759903101}] which is far less than 60s.

After some investigations, we found that Compile costed almost 60s which is unreasonable. 企业微信截图_c99abbd2-7fe5-4164-8013-19f4379a8146

Expected Behavior

No response

Steps to Reproduce

repeatedly run tpch

Additional information

No response

According to the log screenshot, pipeline execution took 190ms. this time consumption is mainly plan build + frondend processing + pull logtail.

Just find the txnid of the problem, and then query out the time consumed by pull logtail to confirm whether it is a pull logtail problem. However, the log level of this environment is info, so the log cannot be seen

I guess the probability is that the pull logtail time is time-consuming, @LeftHandCold PTAL

query table log_info sql

-- query sql
select timestamp, logger_name, caller, message, extra from log_info where (message like '%d4ca868f-cd27-11ed-8701-0a265c8e0804'  or   json_unquote ( json_extract( extra, '$.session_info')) like '%d4ca868f-cd27-11ed-8701-0a265c8e0804') and timestamp < '2023-03-28 05:18:30.123701' and timestamp > '2023-03-28 05:17:20.123701'\G

I guess the probability is that the pull logtail time is time-consuming, @LeftHandCold PTAL

No related log analysis? @zhangxu19830126

ENV

env: eks dev unit
version: nightly-8ceec3e0
S3 bucket: mocloud-test
S3 path prefix:  freetier-01-jJmi
db conn: mysql -h freetier-01.cluster.dev.matrixone.tech -P 6001 -udump -p.... --ssl-mode=DISABLED

timestamp:
- 2023-04-12 07:46:18.703900, mo receive sql
- 2023-04-12 07:46:46.804587, time of Exec.Build: 28s
- 2023-04-12 07:46:46.917512, sql exec done.

-- sql query:
select timestamp, logger_name, caller, message, extra from log_info where (message like '%0e229089-d906-11ed-8d7e-0abd3d4672e3'  or   json_unquote ( json_extract( extra, '$.session_info')) like '%0e229089-d906-11ed-8d7e-0abd3d4672e3') and timestamp > '2023-04-12 07:45:18.123701' and timestamp < '2023-04-12 07:46:50' order by timestamp \G

statement_info record

*************************** 1. row ***************************
     statement_id: 1c59eba2-d906-11ed-8d7e-0abd3d4672e3
   transaction_id: e372fc79-d4af-42d4-ae66-c01e293cad56
       session_id: 0e229089-d906-11ed-8d7e-0abd3d4672e3
          account: mocloud_mo_ob
             user: admin
             host: 10.0.2.201:53748
         database: observability
        statement: insert into mo_ob_metrics.coredns_forward_conn_cache_hits_total (series_id, timestamp, value) values ("ed923f3d3c3d1e667cb6e912f8a31b69", "2023-04-12 07:46:08.657000", 22227.0)
    statement_tag:
statement_fingerprint:
        node_uuid: 37353333-3735-6435-3132-303763653436
        node_type: CN
       request_at: 2023-04-12 07:46:18.703900
      response_at: 2023-04-12 07:46:46.917502
         duration: 28213601967
           status: Success
         err_code: 0
            error:
        exec_plan: {"code": 0, "message": "", "steps": [{"description": "", "graphData": {"edges": [{"dst": "4", "id": "E3", "output": 0, "src": "3", "unit": "count"}, {"dst": "3", "id": "E1", "output": 1, "src": "1", "unit": "count"}, {"dst": "1", "id": "E0", "output": 1, "src": "0", "unit": "count"}], "global": {"statistics": {"IO": [{"name": "Disk IO", "unit": "byte", "value": 0}, {"name": "S3 IO Byte", "unit": "byte", "value": 0}, {"name": "S3 IO Input Count", "unit": "count", "value": 0}, {"name": "S3 IO Output Count", "unit": "count", "value": 0}], "Memory": [{"name": "Memory Size", "unit": "byte", "value": 0}], "Network": [{"name": "Network", "unit": "byte", "value": 0}], "Throughput": [{"name": "Input Rows", "unit": "count", "value": 3}, {"name": "Output Rows", "unit": "count", "value": 3}, {"name": "Input Size", "unit": "byte", "value": 216}, {"name": "Output Size", "unit": "byte", "value": 216}], "Time": [{"name": "Time Consumed", "unit": "ns", "value": 92739}, {"name": "Wait Time", "unit": "ns", "value": 11162}]}, "totalStats": {"name": "Time spent", "unit": "ns", "value": 92739}}, "labels": [], "nodes": [{"id": "4", "labels": [{"name": "Full table name", "value": "mo_ob_metrics.coredns_forward_conn_cache_hits_total"}, {"name": "Columns", "value": ["series_id", "timestamp", "value"]}, {"name": "Total columns", "value": 3}, {"name": "Scan columns", "value": 3}], "name": "Insert", "statistics": {"IO": [{"name": "Disk IO", "unit": "byte", "value": 0}, {"name": "S3 IO Byte", "unit": "byte", "value": 0}, {"name": "S3 IO Input Count", "unit": "count", "value": 0}, {"name": "S3 IO Output Count", "unit": "count", "value": 0}], "Memory": [{"name": "Memory Size", "unit": "byte", "value": 0}], "Network": [{"name": "Network", "unit": "byte", "value": 0}], "Throughput": [{"name": "Input Rows", "unit": "count", "value": 1}, {"name": "Output Rows", "unit": "count", "value": 1}, {"name": "Input Size", "unit": "byte", "value": 72}, {"name": "Output Size", "unit": "byte", "value": 72}], "Time": [{"name": "Time Consumed", "unit": "ns", "value": 1607}, {"name": "Wait Time", "unit": "ns", "value": 11162}, {"name": "Scan Time", "unit": "ns", "value": 0}, {"name": "Insert Time", "unit": "ns", "value": 0}]}, "stats": {"blocknum": 0, "cost": 0, "hashmapsize": 0, "outcnt": 0, "rowsize": 0}, "title": "mo_ob_metrics.coredns_forward_conn_cache_hits_total", "totalStats": {"name": "Time spent", "unit": "ns", "value": 1607}}, {"id": "3", "labels": [{"name": "List of expressions", "value": ["#[0,0]", "#[0,1]", "#[0,2]"]}], "name": "Project", "statistics": {"IO": [{"name": "Disk IO", "unit": "byte", "value": 0}, {"name": "S3 IO Byte", "unit": "byte", "value": 0}, {"name": "S3 IO Input Count", "unit": "count", "value": 0}, {"name": "S3 IO Output Count", "unit": "count", "value": 0}], "Memory": [{"name": "Memory Size", "unit": "byte", "value": 0}], "Network": [{"name": "Network", "unit": "byte", "value": 0}], "Throughput": [{"name": "Input Rows", "unit": "count", "value": 0}, {"name": "Output Rows", "unit": "count", "value": 0}, {"name": "Input Size", "unit": "byte", "value": 0}, {"name": "Output Size", "unit": "byte", "value": 0}], "Time": [{"name": "Time Consumed", "unit": "ns", "value": 0}, {"name": "Wait Time", "unit": "ns", "value": 0}, {"name": "Scan Time", "unit": "ns", "value": 0}, {"name": "Insert Time", "unit": "ns", "value": 0}]}, "stats": {"blocknum": 0, "cost": 1000, "hashmapsize": 0, "outcnt": 1000, "rowsize": 0}, "title": "#[0,0], #[0,1], #[0,2]", "totalStats": {"name": "Time spent", "unit": "ns", "value": 0}}, {"id": "1", "labels": [{"name": "List of expressions", "value": ["_ValueScan.column_0", "_ValueScan.column_1", "_ValueScan.column_2"]}], "name": "Project", "statistics": {"IO": [{"name": "Disk IO", "unit": "byte", "value": 0}, {"name": "S3 IO Byte", "unit": "byte", "value": 0}, {"name": "S3 IO Input Count", "unit": "count", "value": 0}, {"name": "S3 IO Output Count", "unit": "count", "value": 0}], "Memory": [{"name": "Memory Size", "unit": "byte", "value": 0}], "Network": [{"name": "Network", "unit": "byte", "value": 0}], "Throughput": [{"name": "Input Rows", "unit": "count", "value": 1}, {"name": "Output Rows", "unit": "count", "value": 1}, {"name": "Input Size", "unit": "byte", "value": 72}, {"name": "Output Size", "unit": "byte", "value": 72}], "Time": [{"name": "Time Consumed", "unit": "ns", "value": 603}, {"name": "Wait Time", "unit": "ns", "value": 0}, {"name": "Scan Time", "unit": "ns", "value": 0}, {"name": "Insert Time", "unit": "ns", "value": 0}]}, "stats": {"blocknum": 0, "cost": 1000, "hashmapsize": 0, "outcnt": 1000, "rowsize": 0}, "title": "_ValueScan.column_0, _ValueScan.column_1, _ValueScan.column_2", "totalStats": {"name": "Time spent", "unit": "ns", "value": 603}}, {"id": "0", "labels": [{"name": "List of values", "value": ["column_0", "column_1", "column_2"]}], "name": "Values Scan", "statistics": {"IO": [{"name": "Disk IO", "unit": "byte", "value": 0}, {"name": "S3 IO Byte", "unit": "byte", "value": 0}, {"name": "S3 IO Input Count", "unit": "count", "value": 0}, {"name": "S3 IO Output Count", "unit": "count", "value": 0}], "Memory": [{"name": "Memory Size", "unit": "byte", "value": 0}], "Network": [{"name": "Network", "unit": "byte", "value": 0}], "Throughput": [{"name": "Input Rows", "unit": "count", "value": 1}, {"name": "Output Rows", "unit": "count", "value": 1}, {"name": "Input Size", "unit": "byte", "value": 72}, {"name": "Output Size", "unit": "byte", "value": 72}], "Time": [{"name": "Time Consumed", "unit": "ns", "value": 90529}, {"name": "Wait Time", "unit": "ns", "value": 0}, {"name": "Scan Time", "unit": "ns", "value": 0}, {"name": "Insert Time", "unit": "ns", "value": 89956}]}, "stats": {"blocknum": 1, "cost": 1000, "hashmapsize": 0, "outcnt": 1000, "rowsize": 0}, "title": "column_0, column_1, column_2", "totalStats": {"name": "Time spent", "unit": "ns", "value": 90529}}]}, "state": "success", "stats": {}, "step": 0}], "success": true, "uuid": "1c59eba2-d906-11ed-8d7e-0abd3d4672e3"}
        rows_read: 0
       bytes_scan: 0
            stats: {"statistics": {"IO": [{"name": "Disk IO", "unit": "byte", "value": 0}, {"name": "S3 IO Byte", "unit": "byte", "value": 0}, {"name": "S3 IO Input Count", "unit": "count", "value": 0}, {"name": "S3 IO Output Count", "unit": "count", "value": 0}], "Memory": [{"name": "Memory Size", "unit": "byte", "value": 0}], "Network": [{"name": "Network", "unit": "byte", "value": 0}], "Throughput": [{"name": "Input Rows", "unit": "count", "value": 3}, {"name": "Output Rows", "unit": "count", "value": 3}, {"name": "Input Size", "unit": "byte", "value": 216}, {"name": "Output Size", "unit": "byte", "value": 216}], "Time": [{"name": "Time Consumed", "unit": "ns", "value": 92739}, {"name": "Wait Time", "unit": "ns", "value": 11162}]}, "totalStats": {"name": "Time spent", "unit": "ns", "value": 92739}}
   statement_type: Insert
       query_type: DML
          role_id: 2
  sql_source_type: external_sql
     result_count: 0
1 row in set (7.29 sec)

after i download part-of log file to local, query select * from log_info where message like '%Logtail%';

local logfile contain logs between [2023-04-12 07:45:00.690938, 2023-04-12 07:47:12.717123]
there is NO [Logtail] long pull cost ... log record.

with dev image: jacksonxie/matrixone:mo-dev-0a48ecbc8 found new 2 case:

build plan cost most time in buildPlan(...) function

23.739800719s in 23.73986114s ~= 99.999%

mysql>  select trace_id, timestamp, message, extra from log_info where message like '%ba760793-ddcb-11ed-a904-7603475aecd2' or json_extract( extra, '$.session_info') like '%ba760793-ddcb-11ed-a904-7603475aecd2%' order by timestamp\G
*************************** 53. row ***************************
trace_id: da35287c-ddcb-11ed-a904-7603475aecd2
timestamp: 2023-04-18 09:32:16.586378
message: build plan long cost 23.739800719s
extra: {"session_info": "connectionId 7018|10.0.2.192:58024|{account mocloud_mo_ob:admin:accountadmin -- 1:2:2}|ba760793-ddcb-11ed-a904-7603475aecd2"}
*************************** 54. row ***************************
trace_id: 0
timestamp: 2023-04-18 09:32:16.586435
message: time of Exec.Build : 23.73986114s connectionId 7018|10.0.2.192:58024|{account mocloud_mo_ob:admin:accountadmin -- 1:2:2}|ba760793-ddcb-11ed-a904-7603475aecd2
extra: {}
*************************** 55. row ***************************
trace_id: 0
timestamp: 2023-04-18 09:32:16.586498
message: time of Exec.Run : 33.785µs connectionId 7018|10.0.2.192:58024|{account mocloud_mo_ob:admin:accountadmin -- 1:2:2}|ba760793-ddcb-11ed-a904-7603475aecd2
extra: {}
*************************** 56. row ***************************
trace_id: 0
timestamp: 2023-04-18 09:32:16.586524
message: time of SendResponse 150ns connectionId 7018|10.0.2.192:58024|{account mocloud_mo_ob:admin:accountadmin -- 1:2:2}|ba760793-ddcb-11ed-a904-7603475aecd2
extra: {}

there may long cost before while send response

agent logs


2023/04/18 09:31:52.303198 +0000 INFO export/sql_writer.go:131 exec sql:insert into `mo_ob_metrics`.`container_scrape_error` (`series_id`,`timestamp`,`value`) values ("601d76fc977652ce03a6a72a9bc8f960","2023-04-18 09:30:57.280000",0.0) {"span": {"trace_id": "8df324fc-e1ae-eb29-68d2-28826357fc57", "span_id": "66e39400d8069e2d"}}

... 2023/04/18 09:32:07.689655 +0000 ERROR mysql mysql@v1.7.0/packets.go:37 read tcp 10.0.2.111:44428->44.230.223.233:6001: i/o timeout github.com/go-sql-driver/mysql.(mysqlConn).readPacket /go/pkg/mod/github.com/go-sql-driver/mysql@v1.7.0/packets.go:37 github.com/go-sql-driver/mysql.(mysqlConn).readResultSetHeaderPacket /go/pkg/mod/github.com/go-sql-driver/mysql@v1.7.0/packets.go:537 github.com/go-sql-driver/mysql.(mysqlConn).exec /go/pkg/mod/github.com/go-sql-driver/mysql@v1.7.0/connection.go:334 github.com/go-sql-driver/mysql.(mysqlConn).Exec /go/pkg/mod/github.com/go-sql-driver/mysql@v1.7.0/connection.go:316 github.com/go-sql-driver/mysql.(mysqlConn).ExecContext /go/pkg/mod/github.com/go-sql-driver/mysql@v1.7.0/connection.go:525 database/sql.ctxDriverExec /usr/local/go/src/database/sql/ctxutil.go:31 database/sql.(DB).execDC.func2 /usr/local/go/src/database/sql/sql.go:1679 database/sql.withLock /usr/local/go/src/database/sql/sql.go:3439 database/sql.(DB).execDC /usr/local/go/src/database/sql/sql.go:1674 database/sql.(DB).exec /usr/local/go/src/database/sql/sql.go:1659 database/sql.(DB).ExecContext /usr/local/go/src/database/sql/sql.go:1633 github.com/matrixone-cloud/observability/pkg/export.(SqlWriter).FlushAndClose /go/src/github.com/matrixone-cloud/observability/pkg/export/sql_writer.go:132 github.com/matrixorigin/matrixone/pkg/util/export/table.(RowRequest).Handle /go/pkg/mod/github.com/matrixorigin/matrixone@v0.7.1-0.20230331024622-15351144258c/pkg/util/export/table/type.go:333 github.com/matrixorigin/matrixone/pkg/util/trace/impl/motrace.batchETLHandler.NewItemBatchHandler.func1 /go/pkg/mod/github.com/matrixorigin/matrixone@v0.7.1-0.20230331024622-15351144258c/pkg/util/trace/impl/motrace/buffer_pipe.go:87 github.com/matrixorigin/matrixone/pkg/util/trace/impl/motrace.batchETLHandler.NewItemBatchHandler.func2 /go/pkg/mod/github.com/matrixorigin/matrixone@v0.7.1-0.20230331024622-15351144258c/pkg/util/trace/impl/motrace/buffer_pipe.go:100 github.com/matrixorigin/matrixone/pkg/util/export.(bufferExportReq).handle /go/pkg/mod/github.com/matrixorigin/matrixone@v0.7.1-0.20230331024622-15351144258c/pkg/util/export/batch_processor.go:172 github.com/matrixorigin/matrixone/pkg/util/export.(*MOCollector).doExport /go/pkg/mod/github.com/matrixorigin/matrixone@v0.7.1-0.20230331024622-15351144258c/pkg/util/export/batch_processor.go:459 2023/04/18 09:32:07.689875 +0000 WARN export/sql_writer.go:135 failed to exec sql on table mo_ob_metrics.container_scrape_error {"span": {"trace_id": "8df324fc-e1ae-eb29-68d2-28826357fc57", "span_id": "66e39400d8069e2d"}} 2023/04/18 09:32:07.689906 +0000 ERROR export/sql_writer.go:137 sql: insert into mo_ob_metrics.container_scrape_error (series_id,timestamp,value) values ("601d76fc977652ce03a6a72a9bc8f960","2023-04-18 09:30:57.280000",0.0) {"span": {"trace_id": "8df324fc-e1ae-eb29-68d2-28826357fc57", "span_id": "66e39400d8069e2d"}}

- mo logs

[2023-04-18 09:31:52.844045][info][] frontend/util.go:415 time of Exec.Build : 145.051326ms connectionId 7310|10.0.2.192:41960|{account mocloud_mo_ob:admin:accountadmin -- 1:2:2}|cb627cae-ddcb-11ed-a904-7603475aecd2 37353333-3735-6435-3132-303763653436 [CN] trace_id:0 {} [2023-04-18 09:31:52.844730][info][] frontend/util.go:415 time of Exec.Run : 573.942µs connectionId 7310|10.0.2.192:41960|{account mocloud_mo_ob:admin:accountadmin -- 1:2:2}|cb627cae-ddcb-11ed-a904-7603475aecd2 37353333-3735-6435-3132-303763653436 [CN] trace_id:0 {} [2023-04-18 09:31:52.844849][info][] frontend/util.go:415 time of SendResponse 187ns connectionId 7310|10.0.2.192:41960|{account mocloud_mo_ob:admin:accountadmin -- 1:2:2}|cb627cae-ddcb-11ed-a904-7603475aecd2 37353333-3735-6435-3132-303763653436 [CN] trace_id:0 {}

... ( this stage cost 24s, but out with success result, while agent with io timeout at 09:32:07 )

[2023-04-18 09:32:16.585375][info][] frontend/util.go:400 query trace status 37353333-3735-6435-3132-303763653436 [CN] trace_id:da2f5aba-ddcb-11ed-a904-7603475aecd2 {"connection_id": 7310, "session_info": "connectionId 7310|10.0.2.192:41960|{account mocloud_mo_ob:admin:accountadmin -- 1:2:2}|cb627cae-ddcb-11ed-a904-7603475aecd2", "statement": "insert into mo_ob_metrics.container_scrape_error (series_id, timestamp, value) values (\"601d76fc977652ce03a6a72a9bc8f960\", \"2023-04-18 09:30:57.280000\", 0.0)", "status": "success"}

Add more logs waiting for repro

new found: long cost on open txn twice.

try repro from local version: https://github.com/xzxiong/matrixone/commit/9266c7f45e0778bdb1ee1f8167b6a6467bf55782 image: jacksonxie/matrixone:mo-dev-9266c7f45 ( try to run in eks dev )

found the cost pay for open txn. statement_id faf93bac-dea0-11ed-9418-3ebf9f3960c8 build plan cost 5s+

TxnHandler::NewTxn cost 3790 ms
determineUserHasPrivilegeSet cost 1244 ms

both functions are creating new txn.

( statement_info as following )

mysql> mysql> select * from system.statement_info where statement_id = 'faf93bac-dea0-11ed-9418-3ebf9f3960c8'\G
*************************** 1. row ***************************
         statement_id: faf93bac-dea0-11ed-9418-3ebf9f3960c8
       transaction_id: dca26587-d419-473e-abbc-0b176ebcf225
           session_id: efe09c52-de9f-11ed-88f9-3ebf9f3960c8
              account: sys
                 user: dump
                 host: 127.0.0.1:63033
             database: sbtest
            statement: select k from sbtest3 where id = 69242
        statement_tag:
statement_fingerprint:
            node_uuid: 7c4dccb4-4d3c-41f8-b482-5251dc7a41bf
            node_type: ALL
           request_at: 2023-04-19 18:57:30.512425
          response_at: 2023-04-19 18:57:35.551811
             duration: 5039362917
...

trace info while call buildPlan(...)

mysql> select trace_id, span_id, parent_span_id, span_name, start_time, end_time, duration / 1e6 sec from span_info where trace_id = 'faf93bac-dea0-11ed-9418-3ebf9f3960c8' order by start_time;
+--------------------------------------+------------------+------------------+-------------------------------------------------------------------+----------------------------+----------------------------+-------------+
| trace_id                             | span_id          | parent_span_id   | span_name                                                         | start_time                 | end_time                   | sec         |
+--------------------------------------+------------------+------------------+-------------------------------------------------------------------+----------------------------+----------------------------+-------------+
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | f6ac84f4c68d62a9 | 0                | authenticateUserCanExecuteStatement                               | 2023-04-19 18:57:30.512486 | 2023-04-19 18:57:30.512488 |    0.002708 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | cc261c5602dded04 | 0                | buildPlan                                                         | 2023-04-19 18:57:30.512490 | 2023-04-19 18:57:35.550128 |    5037.616 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | fc5ceba8082c69bd | 0                | BaseOptimizer::Optimize                                           | 2023-04-19 18:57:30.512491 | 2023-04-19 18:57:34.305414 | 3792.906542 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | fa491f6c2af855eb | 0                | BuildPlan                                                         | 2023-04-19 18:57:30.512491 | 2023-04-19 18:57:34.305378 |  3792.86975 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 20573689e95e3764 | 0                | TxnCompilerContext::ResolveVariable                               | 2023-04-19 18:57:30.512492 | 2023-04-19 18:57:30.512493 |    0.000875 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | eb5aa3edf867fa1c | 0                | QueryBuilder::buildSelect                                         | 2023-04-19 18:57:30.512566 | 2023-04-19 18:57:34.305197 | 3792.614208 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 5ebf462b7a8f2c94 | 0                | TxnCompilerContext::Resolve                                       | 2023-04-19 18:57:30.512567 | 2023-04-19 18:57:34.303506 | 3790.921542 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 763589b60db831d9 | 0                | TxnHandler::GetTxn                                                | 2023-04-19 18:57:30.512568 | 2023-04-19 18:57:34.303251 | 3790.665541 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | da50b2ecf4fc52ff | 0                | TxnCompilerContext::GetSubscriptionMeta                           | 2023-04-19 18:57:30.512568 | 2023-04-19 18:57:34.303298 | 3790.713625 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 874c79d12e5cedf4 | 0                | TxnHandler::NewTxn                                                | 2023-04-19 18:57:30.512569 | 2023-04-19 18:57:34.303226 | 3790.640166 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 38e900d049cb45ec | 0                | sender.doSend                                                     | 2023-04-19 18:57:30.512620 | 2023-04-19 18:57:30.512867 |    0.247666 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | f09e8e223fe14d5a | 38e900d049cb45ec | server.onMessage                                                  | 2023-04-19 18:57:30.512682 | 2023-04-19 18:57:30.512822 |    0.140334 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 11ac4d7929e09790 | 0                | sender.doSend                                                     | 2023-04-19 18:57:30.517530 | 2023-04-19 18:57:30.517809 |    0.279291 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | e023f96116099d50 | 11ac4d7929e09790 | server.onMessage                                                  | 2023-04-19 18:57:30.517584 | 2023-04-19 18:57:30.517791 |     0.20675 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 60a10559e8341a28 | 0                | sender.doSend                                                     | 2023-04-19 18:57:34.302115 | 2023-04-19 18:57:34.303096 |    0.980625 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 0e194c66b8b5e6b5 | 60a10559e8341a28 | server.onMessage                                                  | 2023-04-19 18:57:34.302741 | 2023-04-19 18:57:34.302945 |    0.204667 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 2dff635ba34bbdce | da50b2ecf4fc52ff | getSubscriptionMeta                                               | 2023-04-19 18:57:34.303278 | 2023-04-19 18:57:34.303298 |    0.019916 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 64236672203e8405 | 2dff635ba34bbdce | Engine::Database                                                  | 2023-04-19 18:57:34.303293 | 2023-04-19 18:57:34.303298 |    0.004375 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 296a0e6ad9341fef | 0                | TxnCompilerContext::getRelation                                   | 2023-04-19 18:57:34.303316 | 2023-04-19 18:57:34.303478 |    0.162583 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | ca5b77daecff0d8d | 0                | TxnHandler::GetTxn                                                | 2023-04-19 18:57:34.303346 | 2023-04-19 18:57:34.303346 |    0.000333 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 7fca3ab8cbc61118 | 0                | Engine::Database                                                  | 2023-04-19 18:57:34.303350 | 2023-04-19 18:57:34.303351 |    0.000959 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 11f02f3d346c0010 | 0                | txnDatabase::Relation                                             | 2023-04-19 18:57:34.303351 | 2023-04-19 18:57:34.303478 |    0.126584 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 7e5f05ba4d4f4664 | 0                | TxnCompilerContext::getTableDef                                   | 2023-04-19 18:57:34.303490 | 2023-04-19 18:57:34.303506 |    0.015166 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | e7e61d51b8fa1d60 | 0                | TxnCompilerContext::GetSubscriptionMeta                           | 2023-04-19 18:57:34.303515 | 2023-04-19 18:57:34.303530 |    0.014833 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | def3fa9a76a92a57 | 0                | TxnHandler::GetTxn                                                | 2023-04-19 18:57:34.303518 | 2023-04-19 18:57:34.303518 |    0.000292 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 776fb393d982c88c | e7e61d51b8fa1d60 | getSubscriptionMeta                                               | 2023-04-19 18:57:34.303527 | 2023-04-19 18:57:34.303530 |     0.00225 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 9ff36d92ddea322f | 776fb393d982c88c | Engine::Database                                                  | 2023-04-19 18:57:34.303528 | 2023-04-19 18:57:34.303530 |    0.001417 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 9e3b50bf5b0f0b1b | 0                | TxnCompilerContext::getRelation                                   | 2023-04-19 18:57:34.303533 | 2023-04-19 18:57:34.303542 |    0.008292 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | af861d2eeacdd3a6 | 0                | TxnHandler::GetTxn                                                | 2023-04-19 18:57:34.303534 | 2023-04-19 18:57:34.303535 |    0.000292 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 13350072fd467f86 | 0                | Engine::Database                                                  | 2023-04-19 18:57:34.303537 | 2023-04-19 18:57:34.303538 |    0.000875 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 49b412498a0fc50e | 0                | txnDatabase::Relation                                             | 2023-04-19 18:57:34.303541 | 2023-04-19 18:57:34.303542 |    0.000583 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 5aaf8efc0250844d | 0                | txnTable::Stats                                                   | 2023-04-19 18:57:34.303546 | 2023-04-19 18:57:34.305045 |      1.4985 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | d6d90b6fc473371b | 5aaf8efc0250844d | sender.doSend                                                     | 2023-04-19 18:57:34.304058 | 2023-04-19 18:57:34.304722 |    0.663708 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | e20e021620534e3a | d6d90b6fc473371b | server.onMessage                                                  | 2023-04-19 18:57:34.304525 | 2023-04-19 18:57:34.304677 |    0.152083 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 332177cf11596f87 | 0                | baseBinder::baseBindExpr                                          | 2023-04-19 18:57:34.305153 | 2023-04-19 18:57:34.305170 |    0.016959 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 68a987898c8c2985 | 0                | baseBinder::baseBindExpr                                          | 2023-04-19 18:57:34.305159 | 2023-04-19 18:57:34.305161 |    0.001958 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | ec4b1b0d911ae894 | 0                | baseBinder::baseBindExpr                                          | 2023-04-19 18:57:34.305165 | 2023-04-19 18:57:34.305166 |    0.000792 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 75b1d3a8c0bbae99 | 0                | baseBinder::baseBindExpr                                          | 2023-04-19 18:57:34.305173 | 2023-04-19 18:57:34.305174 |    0.000792 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | e7a8868d7b1056b1 | 0                | QueryBuilder::createQuery                                         | 2023-04-19 18:57:34.305256 | 2023-04-19 18:57:34.305378 |    0.121875 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 3bebb5344e4a96fb | 0                | TxnCompilerContext::GetSubscriptionMeta                           | 2023-04-19 18:57:34.305270 | 2023-04-19 18:57:34.305285 |    0.015125 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 2b491dd9d0fa1526 | 0                | TxnHandler::GetTxn                                                | 2023-04-19 18:57:34.305271 | 2023-04-19 18:57:34.305271 |     0.00025 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 888ffc4797f39ffa | 3bebb5344e4a96fb | getSubscriptionMeta                                               | 2023-04-19 18:57:34.305277 | 2023-04-19 18:57:34.305285 |    0.007875 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 65841bd0a381410f | 888ffc4797f39ffa | Engine::Database                                                  | 2023-04-19 18:57:34.305278 | 2023-04-19 18:57:34.305285 |       0.007 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | f7f12868eafeff18 | 0                | TxnCompilerContext::getRelation                                   | 2023-04-19 18:57:34.305286 | 2023-04-19 18:57:34.305300 |    0.013792 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 75db0955f895c351 | 0                | TxnHandler::GetTxn                                                | 2023-04-19 18:57:34.305292 | 2023-04-19 18:57:34.305292 |    0.000208 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 5b5041e362517a88 | 0                | Engine::Database                                                  | 2023-04-19 18:57:34.305295 | 2023-04-19 18:57:34.305298 |       0.003 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 1f51303ca9188cdc | 0                | txnDatabase::Relation                                             | 2023-04-19 18:57:34.305299 | 2023-04-19 18:57:34.305300 |     0.00075 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 61621f30f7b2df4b | 0                | txnTable::Stats                                                   | 2023-04-19 18:57:34.305327 | 2023-04-19 18:57:34.305363 |      0.0365 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | ce6f2a56a6554462 | 0                | BaseOptimizer::optimize                                           | 2023-04-19 18:57:34.305379 | 2023-04-19 18:57:34.305385 |    0.006167 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 06eba4ef25a1ef0b | cc261c5602dded04 | authenticateCanExecuteStatementAndPlan                            | 2023-04-19 18:57:34.305420 | 2023-04-19 18:57:35.550128 | 1244.702125 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 2f2ac3e1683989d0 | 06eba4ef25a1ef0b | authenticateUserCanExecuteStatementWithObjectTypeDatabaseAndTable | 2023-04-19 18:57:34.305428 | 2023-04-19 18:57:35.550127 | 1244.693916 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | ff687e36f11cdd38 | 2f2ac3e1683989d0 | determineUserHasPrivilegeSet                                      | 2023-04-19 18:57:34.305451 | 2023-04-19 18:57:35.550127 | 1244.670292 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | c4e04301c207f721 | ff687e36f11cdd38 | TxnHandler::GetTxn                                                | 2023-04-19 18:57:35.550035 | 2023-04-19 18:57:35.550036 |    0.000416 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 1f49b9b693faf3b9 | 0                | TxnHandler::GetTxn                                                | 2023-04-19 18:57:35.550445 | 2023-04-19 18:57:35.550445 |    0.000416 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 3504bd7e358da7f2 | 0                | Engine::Database                                                  | 2023-04-19 18:57:35.550488 | 2023-04-19 18:57:35.550490 |    0.001958 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 9128ecf3044ed66c | 0                | txnDatabase::Relation                                             | 2023-04-19 18:57:35.550490 | 2023-04-19 18:57:35.550560 |     0.06925 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | d29bcd27363330b1 | 0                | txnTable::Ranges                                                  | 2023-04-19 18:57:35.550584 | 2023-04-19 18:57:35.550682 |    0.098083 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 92e32763558976da | 0                | Engine::Database                                                  | 2023-04-19 18:57:35.550706 | 2023-04-19 18:57:35.550707 |    0.001625 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 44ebf836dd4d3659 | 0                | txnDatabase::Relation                                             | 2023-04-19 18:57:35.550813 | 2023-04-19 18:57:35.550813 |    0.000542 |
| faf93bac-dea0-11ed-9418-3ebf9f3960c8 | 6b43125c759fe24b | 0                | TxnHandler::GetTxn                                                | 2023-04-19 18:57:35.550831 | 2023-04-19 18:57:35.550831 |    0.000334 |
+--------------------------------------+------------------+------------------+-------------------------------------------------------------------+----------------------------+----------------------------+-------------+
60 rows in set (0.62 sec)

dev env result: long cost on open txn.

as run in eks env with image: jacksonxie/matrixone:mo-dev-9266c7f45

there is one cost 11s query:

select account_id, account_name, status, suspended_time from mo_catalog.mo_account where account_name = "9989e8e8_a0b5_4657_83d4_4a1490c995d7"

logs


{"level":"INFO","time":"2023/04/19 13:06:41.401077 +0000","caller":"frontend/util.go:400","msg":"build plan long cost 11.141748129s","span":{"trace_id":"0038e04a-deb3-11ed-aacb-82f1fb9c3e97","kind":"statement"},"session_info":""}

{"level":"INFO","time":"2023/04/19 13:06:41.402329 +0000","caller":"frontend/util.go:415","msg":"time of Exec.Build : 11.39562259s "}

{"level":"INFO","time":"2023/04/19 13:06:41.406365 +0000","caller":"frontend/util.go:400","msg":"query trace status","connection_id":4294967295,"statement":"select account_id, account_name, status, suspended_time from mo_catalog.mo_account where account_name = \"9989e8e8_a0b5_4657_83d4_4a1490c995d7\"","status":"success","span":{"trace_id":"0038e04a-deb3-11ed-aacb-82f1fb9c3e97","kind":"statement"},"session_info":""}


- as trace info show: `TxnHandler::NewTxn` cost  11s

mysql> select trace_id, span_id, parent_span_id, +--------------------------------------+------------------+-- | trace_id | span_id +--------------------------------------+------------------+-- | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | f13ff77744906084 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 7d2190c18db603eb | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 8cd7f106c06d0a8a | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | d1004761cca1371d | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | f7e2105c3da464fc | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 54ccb6cc8d7b6c81 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 8c0e9d0686134fc5 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 04880542065efae6 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 2ed6b79ca6935fe7 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | a9684190b63fd385 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 629e5963bf91c144 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 188c20cac7c00523 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 86c92e23e0ddbdbe | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 112bea75f8a9848e | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | dcd985a62c37b3ee | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | ddb38c0372bd17d3 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 89281512130beb15 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 01c1af52981123be | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | d353bda51abd335e | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 338fb08dfc8f32c1 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 12f4fd19f7878043 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 7f46fc2dc4d3da45 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 2d88544d82c714bf | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 9bd22100f79298b4 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 0412b3f9bade39a5 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 360d2fd5bb567a54 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 6db747c2baa1de6f | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 5015cbf892ad6c99 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 5a922140aa7c2af0 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 4f6311ae72e00de1 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | f45d3de72c0686e1 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 444000760901c74a | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 44c06d05ef8f2b6f | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 3c7a93b2fe21ec19 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 1ed0a08093a09a80 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | 17314cbbc9d970b6 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | bc2aa7928231dcc2 | 0 | 0038e04a-deb3-11ed-aacb-82f1fb9c3e97 | d33346102e25d5c1 | 0 +--------------------------------------+------------------+-- 38 rows in set (19 min 31.80 sec) span_name, duration / 1e6 ms, start_time, end_time from system.span_info where trace_id = '0038e04a-deb3-11ed-aacb-82f1fb9c3e97' and mo_log_date(__mo_filepath) = '2023-04-19' order by start_time; --------------+-------------------------------------+--------------+----------------------------+----------------------------+ | parent_span_id | span_name | ms | start_time | end_time | --------------+-------------------------------------+--------------+----------------------------+----------------------------+ | buildPlan | 11141.746958 | 2023-04-19 13:06:30.259325 | 2023-04-19 13:06:41.401072 | | BuildPlan | 11141.735474 | 2023-04-19 13:06:30.259327 | 2023-04-19 13:06:41.401063 | | BaseOptimizer::Optimize | 11141.744231 | 2023-04-19 13:06:30.259327 | 2023-04-19 13:06:41.401071 | | TxnCompilerContext::ResolveVariable | 0.001235 | 2023-04-19 13:06:30.259328 | 2023-04-19 13:06:30.259329 | | QueryBuilder::buildSelect | 11141.679768 | 2023-04-19 13:06:30.259342 | 2023-04-19 13:06:41.401022 | | TxnCompilerContext::Resolve | 11141.558406 | 2023-04-19 13:06:30.259344 | 2023-04-19 13:06:41.400902 | | TxnCompilerContext::getRelation | 11141.546347 | 2023-04-19 13:06:30.259344 | 2023-04-19 13:06:41.400891 | | TxnHandler::GetTxn | 11141.469705 | 2023-04-19 13:06:30.259350 | 2023-04-19 13:06:41.400820 | | TxnHandler::NewTxn | 11141.466395 | 2023-04-19 13:06:30.259351 | 2023-04-19 13:06:41.400817 | | Engine::Database | 0.003619 | 2023-04-19 13:06:41.400822 | 2023-04-19 13:06:41.400825 | | txnDatabase::Relation | 0.063365 | 2023-04-19 13:06:41.400826 | 2023-04-19 13:06:41.400890 | | TxnCompilerContext::getTableDef | 0.010285 | 2023-04-19 13:06:41.400891 | 2023-04-19 13:06:41.400902 | | TxnCompilerContext::getRelation | 0.010179 | 2023-04-19 13:06:41.400906 | 2023-04-19 13:06:41.400917 | | TxnHandler::GetTxn | 0.000887 | 2023-04-19 13:06:41.400910 | 2023-04-19 13:06:41.400911 | | Engine::Database | 0.002439 | 2023-04-19 13:06:41.400912 | 2023-04-19 13:06:41.400914 | | txnDatabase::Relation | 0.001631 | 2023-04-19 13:06:41.400915 | 2023-04-19 13:06:41.400916 | | txnTable::Stats | 0.00087 | 2023-04-19 13:06:41.400918 | 2023-04-19 13:06:41.400919 | | baseBinder::baseBindExpr | 0.017994 | 2023-04-19 13:06:41.400932 | 2023-04-19 13:06:41.400950 | | baseBinder::baseBindExpr | 0.002486 | 2023-04-19 13:06:41.400934 | 2023-04-19 13:06:41.400936 | | baseBinder::baseBindExpr | 0.002041 | 2023-04-19 13:06:41.400937 | 2023-04-19 13:06:41.400939 | | baseBinder::baseBindExpr | 0.001838 | 2023-04-19 13:06:41.400955 | 2023-04-19 13:06:41.400956 | | baseBinder::baseBindExpr | 0.002625 | 2023-04-19 13:06:41.400958 | 2023-04-19 13:06:41.400961 | | baseBinder::baseBindExpr | 0.002035 | 2023-04-19 13:06:41.400963 | 2023-04-19 13:06:41.400965 | | baseBinder::baseBindExpr | 0.001707 | 2023-04-19 13:06:41.400967 | 2023-04-19 13:06:41.400969 | | QueryBuilder::createQuery | 0.038618 | 2023-04-19 13:06:41.401023 | 2023-04-19 13:06:41.401062 | | TxnCompilerContext::getRelation | 0.006859 | 2023-04-19 13:06:41.401040 | 2023-04-19 13:06:41.401047 | | TxnHandler::GetTxn | 0.000763 | 2023-04-19 13:06:41.401043 | 2023-04-19 13:06:41.401043 | | Engine::Database | 0.001524 | 2023-04-19 13:06:41.401044 | 2023-04-19 13:06:41.401045 | | txnDatabase::Relation | 0.00095 | 2023-04-19 13:06:41.401046 | 2023-04-19 13:06:41.401047 | | txnTable::Stats | 0.00053 | 2023-04-19 13:06:41.401049 | 2023-04-19 13:06:41.401050 | | BaseOptimizer::optimize | 0.00707 | 2023-04-19 13:06:41.401063 | 2023-04-19 13:06:41.401070 | | TxnHandler::GetTxn | 0.000575 | 2023-04-19 13:06:41.401107 | 2023-04-19 13:06:41.401108 | | Engine::Database | 0.001496 | 2023-04-19 13:06:41.401136 | 2023-04-19 13:06:41.401137 | | txnDatabase::Relation | 0.000874 | 2023-04-19 13:06:41.401138 | 2023-04-19 13:06:41.401139 | | txnTable::Ranges | 2.690526 | 2023-04-19 13:06:41.401143 | 2023-04-19 13:06:41.403834 | | Engine::Database | 0.002722 | 2023-04-19 13:06:41.403864 | 2023-04-19 13:06:41.403867 | | txnDatabase::Relation | 0.001776 | 2023-04-19 13:06:41.403868 | 2023-04-19 13:06:41.403870 | | TxnHandler::GetTxn | 0.000779 | 2023-04-19 13:06:41.403889 | 2023-04-19 13:06:41.403890 | --------------+-------------------------------------+--------------+----------------------------+----------------------------+

two case stack branch: https://github.com/xzxiong/matrixone/tree/dev_log_exec_build

TxnHandler::NewTxn

github.com/matrixorigin/matrixone/pkg/frontend.(*TxnHandler).NewTxn.func1
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/txn.go:161
github.com/matrixorigin/matrixone/pkg/frontend.(*TxnHandler).NewTxn
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/txn.go:198
github.com/matrixorigin/matrixone/pkg/frontend.(*Session).TxnCreate
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/txn.go:497
github.com/matrixorigin/matrixone/pkg/frontend.(*TxnHandler).GetTxn
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/txn.go:383
github.com/matrixorigin/matrixone/pkg/frontend.(*TxnCompilerContext).GetSubscriptionMeta
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/compiler_context.go:735
github.com/matrixorigin/matrixone/pkg/frontend.(*TxnCompilerContext).ensureDatabaseIsNotEmpty
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/compiler_context.go:244
github.com/matrixorigin/matrixone/pkg/frontend.(*TxnCompilerContext).Resolve
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/compiler_context.go:268
github.com/matrixorigin/matrixone/pkg/sql/plan.(*QueryBuilder).buildTable
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/sql/plan/query_builder.go:1894
github.com/matrixorigin/matrixone/pkg/sql/plan.(*QueryBuilder).buildTable
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/sql/plan/query_builder.go:2021
github.com/matrixorigin/matrixone/pkg/sql/plan.(*QueryBuilder).buildTable
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/sql/plan/query_builder.go:2001
github.com/matrixorigin/matrixone/pkg/sql/plan.(*QueryBuilder).buildFrom
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/sql/plan/query_builder.go:1780
github.com/matrixorigin/matrixone/pkg/sql/plan.(*QueryBuilder).buildSelect
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/sql/plan/query_builder.go:1391
github.com/matrixorigin/matrixone/pkg/sql/plan.runBuildSelectByBinder
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/sql/plan/build.go:29
github.com/matrixorigin/matrixone/pkg/sql/plan.BuildPlan
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/sql/plan/build.go:62
github.com/matrixorigin/matrixone/pkg/sql/plan.(*BaseOptimizer).Optimize
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/sql/plan/optimize.go:59
github.com/matrixorigin/matrixone/pkg/frontend.buildPlan
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/mysql_cmd_executor.go:1410
github.com/matrixorigin/matrixone/pkg/frontend.(*TxnComputationWrapper).Compile
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/computation_wrapper.go:202
github.com/matrixorigin/matrixone/pkg/frontend.(*MysqlCmdExecutor).doComQuery
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/mysql_cmd_executor.go:2686
github.com/matrixorigin/matrixone/pkg/frontend.(*MysqlCmdExecutor).ExecRequest
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/mysql_cmd_executor.go:3265
github.com/matrixorigin/matrixone/pkg/frontend.(*Routine).handleRequest
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/routine.go:175
github.com/matrixorigin/matrixone/pkg/frontend.(*RoutineManager).Handler
/Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/routine_manager.go:323
github.com/fagongzi/goetty/v2.(*server).doConnection
/Users/jacksonxie/go/pkg/mod/github.com/matrixorigin/goetty/v2@v2.0.0-20221212132037-abf2d4c05484/application.go:381
github.com/fagongzi/goetty/v2.(*server).doStart.func2.1
/Users/jacksonxie/go/pkg/mod/github.com/matrixorigin/goetty/v2@v2.0.0-20221212132037-abf2d4c05484/application.go:344

determineUserHasPrivilegeSet

github.com/matrixorigin/matrixone/pkg/frontend.(*TxnHandler).NewTxn.func1
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/txn.go:161
github.com/matrixorigin/matrixone/pkg/frontend.(*TxnHandler).NewTxn
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/txn.go:198
github.com/matrixorigin/matrixone/pkg/frontend.(*Session).TxnBegin
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/txn.go:536
github.com/matrixorigin/matrixone/pkg/frontend.(*MysqlCmdExecutor).doComQuery
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/mysql_cmd_executor.go:2373
github.com/matrixorigin/matrixone/pkg/frontend.(*BackgroundHandler).Exec
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/session.go:1505
github.com/matrixorigin/matrixone/pkg/frontend.determineUserHasPrivilegeSet
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/authenticate.go:5323
github.com/matrixorigin/matrixone/pkg/frontend.authenticateUserCanExecuteStatementWithObjectTypeDatabaseAndTable
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/authenticate.go:5763
github.com/matrixorigin/matrixone/pkg/frontend.authenticateCanExecuteStatementAndPlan
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/mysql_cmd_executor.go:2076
github.com/matrixorigin/matrixone/pkg/frontend.buildPlan
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/mysql_cmd_executor.go:1424
github.com/matrixorigin/matrixone/pkg/frontend.(*TxnComputationWrapper).Compile
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/computation_wrapper.go:202
github.com/matrixorigin/matrixone/pkg/frontend.(*MysqlCmdExecutor).doComQuery
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/mysql_cmd_executor.go:2686
github.com/matrixorigin/matrixone/pkg/frontend.(*MysqlCmdExecutor).ExecRequest
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/mysql_cmd_executor.go:3265
github.com/matrixorigin/matrixone/pkg/frontend.(*Routine).handleRequest
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/routine.go:175
github.com/matrixorigin/matrixone/pkg/frontend.(*RoutineManager).Handler
    /Users/jacksonxie/go/src/github.com/matrixorigin/matrixone/pkg/frontend/routine_manager.go:323
github.com/fagongzi/goetty/v2.(*server).doConnection
    /Users/jacksonxie/go/pkg/mod/github.com/matrixorigin/goetty/v2@v2.0.0-20221212132037-abf2d4c05484/application.go:381
github.com/fagongzi/goetty/v2.(*server).doStart.func2.1
    /Users/jacksonxie/go/pkg/mod/github.com/matrixorigin/goetty/v2@v2.0.0-20221212132037-abf2d4c05484/application.go:344

with branch code: https://github.com/xzxiong/matrixone/tree/dev_log_exec_build

repro local disk

startup mo-service

./mo-service -debug-http 127.0.0.1:8123 -allocs-profile ./allocs.profile -launch ./etc/launch-tae-CN-tae-DN/launch.toml > mo-service.log

call mo-sysbench prepare

## clone mo-sysbench
git clone git@github.com:matrixorigin/mo-sysbench.git
cd mo-sysbench
## do prepare
mysql -h127.0.0.1 -udump -p111 -P6001 -e "create database if not exists sbtest;"
sysbench  --mysql-host=127.0.0.1 --mysql-port=6001 --mysql-user=dump --mysql-password=111 oltp_common.lua  --mysql-db=sbtest --tables=10 --table_size=100000 --threads=1 --time=30 --report-interval=10 --create_secondary=off  --auto_inc=off prepare

call mo-load test

git clone git@github.com:matrixorigin/mo-load.git
## start point query
cd mo-load
./start.sh -c cases/sysbench/point_select_10_100000 -t 50

watch long cost log ( need branch code https://github.com/xzxiong/matrixone/tree/dev_log_exec_build)

tailf mo-service.log | grep "long cost"

or query Exec.Build which cost > 1s

mysql> select trace_id, timestamp, message, extra from log_info where message like '%Exec.Build%' and message not like '%ms%' and message not like '%µs%' ;

@LeftHandCold Could you kindly have a look?

matrixorigin / matrixone