trace_test.go:390: received trace: "rows affected: 0" // "[n1,client=127.0.0.1:54220,hostssl,user=root,intExec=get-plan-hints]" // "sql/conn_executor_exec.go:1084"
    trace_test.go:390: received trace: "[Open pos:3] executing Sync" // "[n1,client=127.0.0.1:54220,hostssl,user=root,intExec=get-plan-hints]" // "sql/conn_executor.go:2380"
    trace_test.go:390: received trace: "=== SPAN START: commit sql txn ===" // "" // ""
    trace_test.go:390: received trace: "AutoCommit. err: <nil>" // "[n1,client=127.0.0.1:54220,hostssl,user=root,intExec=get-plan-hints]" // "sql/conn_executor_exec.go:4133"
    trace_test.go:390: received trace: "releasing 2 descriptors" // "[n1,client=127.0.0.1:54220,hostssl,user=root,intExec=get-plan-hints]" // "sql/catalog/descs/leased_descriptors.go:400"
    trace_test.go:390: received trace: "release: 1(\"system\",010180b042c03290064e77874e69b0bd6969ec) ver=1:0,0, refcount=0" // "[n1,client=127.0.0.1:54220,hostssl,user=root,intExec=get-plan-hints]" // "sql/catalog/lease/descriptor_state.go:274"
    trace_test.go:390: received trace: "release: 76(\"statement_hints\",010180b042c03290064e77874e69b0bd6969ec) ver=1:0,0, refcount=0" // "[n1,client=127.0.0.1:54220,hostssl,user=root,intExec=get-plan-hints]" // "sql/catalog/lease/descriptor_state.go:274"
    trace_test.go:390: received trace: "finishing connExecutor" // "[n1,client=127.0.0.1:54220,hostssl,user=root,intExec=get-plan-hints]" // "sql/conn_executor.go:1412"
    trace_test.go:390: received trace: "releasing 0 descriptors" // "[n1,client=127.0.0.1:54220,hostssl,user=root,intExec=get-plan-hints]" // "sql/catalog/descs/leased_descriptors.go:400"
    trace_test.go:390: received trace: "finished reading hints for query SELECT _" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/hints/hint_cache.go:492"
    trace_test.go:390: received trace: "planning starts: SELECT" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/exec_util.go:3103"
    trace_test.go:390: received trace: "=== SPAN START: optimizer ===" // "" // ""
    trace_test.go:390: received trace: "query cache miss" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/plan_opt.go:516"
    trace_test.go:390: received trace: "optbuilder start" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/opt/optbuilder/builder.go:244"
    trace_test.go:390: received trace: "optbuilder finish" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/opt/optbuilder/builder.go:280"
    trace_test.go:390: received trace: "optimize start" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/opt/xform/optimizer.go:251"
    trace_test.go:390: received trace: "optimize finish" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/opt/xform/optimizer.go:288"
    trace_test.go:390: received trace: "query cache add" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/plan_opt.go:516"
    trace_test.go:390: received trace: "planning ends" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/conn_executor_exec.go:1084"
    trace_test.go:390: received trace: "checking distributability" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/conn_executor_exec.go:1084"
    trace_test.go:390: received trace: "will distribute plan: false" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/conn_executor_exec.go:1084"
    trace_test.go:390: received trace: "world" // "[n1,client=127.0.0.1:54220,hostssl,user=root,hello=[::666]]" // "sql_test/trace_test.go:345"
    trace_test.go:390: received trace: "execution starts: distributed engine" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/conn_executor_exec.go:1084"
    trace_test.go:390: received trace: "=== SPAN START: consuming rows ===" // "" // ""
    trace_test.go:390: received trace: "creating DistSQL plan with isLocal=true" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/distsql_running.go:2321"
    trace_test.go:390: received trace: "noMutations = true" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/distsql_running.go:767"
    trace_test.go:390: received trace: "containsLocking = false" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/distsql_running.go:817"
    trace_test.go:390: received trace: "must use root txn due to \"values\" wrapped planNode" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/distsql_running.go:840"
    trace_test.go:390: received trace: "running DistSQL plan" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/distsql_running.go:936"
    trace_test.go:390: received trace: "=== SPAN START: flow ===" // "" // ""
    trace_test.go:390: received trace: "setting up vectorized flow" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/colflow/vectorized_flow.go:228"
    trace_test.go:390: received trace: "planning a row-execution processor in the vectorized flow: LocalPlanNode core needs to be wrapped" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/colexec/colbuilder/execplan.go:584"
    trace_test.go:390: received trace: "vectorized flow setup succeeded" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/colflow/vectorized_flow.go:269"
    trace_test.go:390: received trace: "starting (0 processors, 0 startables) asynchronously" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/flowinfra/flow.go:460"
    trace_test.go:390: received trace: "running the batch flow coordinator in the flow's goroutine" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/colflow/vectorized_flow.go:316"
    trace_test.go:390: received trace: "=== SPAN START: batch flow coordinator ===" // "" // ""
    trace_test.go:390: received trace: "=== SPAN START: columnarizer ===" // "" // ""
    trace_test.go:390: received trace: "=== SPAN START: values ===" // "" // ""
    trace_test.go:390: received trace: "ComponentStats{ID: {a0c3a8e7-6638-4558-9ef7-7870118c334c PROCESSOR 0 1 }, execution time: 143µs, sql cpu time: 143µs, batches output: 1, rows output: 1}" // "" // ""
    trace_test.go:390: received trace: "ComponentStats{ID: {00000000-0000-0000-0000-000000000000 UNSET 0 ? }}" // "" // ""
    trace_test.go:390: received trace: "ComponentStats{ID: {a0c3a8e7-6638-4558-9ef7-7870118c334c FLOW 0 1 }}" // "" // ""
    trace_test.go:390: received trace: "execution ends" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/conn_executor_exec.go:1084"
    trace_test.go:390: received trace: "rows affected: 1" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/conn_executor_exec.go:1084"
    trace_test.go:390: received trace: "=== SPAN START: commit sql txn ===" // "" // ""
    trace_test.go:390: received trace: "AutoCommit. err: <nil>" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/conn_executor_exec.go:4133"
    trace_test.go:390: received trace: "releasing 0 descriptors" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/catalog/descs/leased_descriptors.go:400"
    trace_test.go:390: received trace: "[NoTxn pos:3] executing Sync" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/conn_executor.go:2380"
    trace_test.go:390: received trace: "[NoTxn pos:4] executing ExecStmt: SET TRACING = off" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/conn_executor.go:2380"
    trace_test.go:390: received trace: "executing: SET TRACING = off in state: NoTxn" // "[n1,client=127.0.0.1:54220,hostssl,user=root]" // "sql/conn_executor_exec.go:128"
--- FAIL: TestTraceFieldDecomposition/SHOW_TRACE (0.02s)