The captured pprof of Test and Benchmark protobuf cannot be decoded properly

[YangKeao]

This issue does not affect the /debug/pprof/profile of tidb server. The labels of profiles are removed in buildProfileData. It only affects the developers who wants to profile the Benchmark or Test, or profile through the pprof command directly.

It can be easily reproduced by running go test -run 'BenchmarkPointGet' -bench 'BenchmarkPointGet' . -cpuprofile cpu.out in /pkg/session.

With the output, the pprof command will return:

(pprof) web
Warning: syntax ambiguity - badly delimited number '0.09s' in line 53 of <stdin> splits into two tokens
Error: <stdin>: syntax error in line 53 near 's'
failed to execute dot. Is Graphviz installed? Error: exit status 1

It's because we are using non-utf8 bytes in the goroutine labels. If you use dot to dump a dot file (which allows non-utf8 bytes, at least didn't return an error), you will find following things:

�����@K8��`��܋���_����\nsql_digest:Ko�=�c�|�^uyS5l),�1������
�h��" id="N30_0" fontsize=8 shape=box3d tooltip="0.15s"]
N30 -> N30_0 [label=" 0.15s" weight=100 tooltip="0.15s" labeltooltip="0.15s"]
N31 [label="planner\nOptimize\n0.01s (0.14%)\nof 0.14s (2.02%)" id="node31" fontsize=12 shape=box tooltip="github.com/pingcap/tidb/pkg/planner.Optimize (0.14s)" color="#b2aca0" fillcolor="#edecea"]
N31_0 [label = "plan_digest:f����)
�����@K8��`��܋���_����\nsql_digest:Ko�=�c�|�^uyS5l),�1������
�h��" id="N31_0" fontsize=8 shape=box3d tooltip="0.14s"]
N31 -> N31_0 [label=" 0.14s" weight=100 tooltip="0.14s" labeltooltip="0.14s"]
N32 [label="executor\n(*projectionInputFetcher)\nrun\n0 of 0.07s (1.01%)" id="node32" fontsize=8 shape=box tooltip="github.com/pingcap/tidb/pkg/executor.(*projectionInputFetcher).run (0.07s)" color="#b2b0a9" fillcolor="#edeceb"]
N33 [label="aggregate\n(*HashAggExec)\nOpen\n0 of 0.14s (2.02%)" id="node33" fontsize=8 shape=box tooltip="github.com/pingcap/tidb/pkg/executor/aggregate.(*HashAggExec).Open (0.14s)" color="#b2aca0" fillcolor="#edecea"]
N33_0 [label = "plan_digest:)HJ���;�!��*e�w�w���C�;�:zEi��\nsql_digest:�?B�8�c<V~�s��$6yߧ~�����Cn�" id="N33_0" fontsize=8 shape=box3d tooltip="0.09s"]
N33 -> N33_0 [label=" 0.09s" weight=100 tooltip="0.09s" labeltooltip="0.09s"]
N33_1 [label = "plan_digest:�(ɾ�K/?�]�ø`�o��$�n��P�i��{�
                                                        \nsql_digest:��7��4B9�qWL�a������X�
'0�" id="N33_1" fontsize=8 shape=box3d tooltip="0.05s"]
N33 -> N33_1 [label=" 0.05s" weight=100 tooltip="0.05s" labeltooltip="0.05s"]
N34 [label="runtime\nfutex\n0.07s (1.01%)" id="node34" fontsize=18 shape=box tooltip="runtime.futex (0.07s)" color="#b2b0a9" fillcolor="#edeceb"]
N35 [label="runtime\nusleep\n0.07s (1.01%)" id="node35" fontsize=18 shape=box tooltip="runtime.usleep (0.07s)" color="#b2b0a9" fillcolor="#edeceb"]
N36 [label="session\n(*session)\nParseSQL\n0.02s (0.29%)\nof 0.31s (4.47%)" id="node36" fontsize=14 shape=box tooltip="github.com/pingcap/tidb/pkg/session.(*session).ParseSQL (0.31s)" color="#b2a28a" fillcolor="#edebe7"]
N36_0 [label = "plan_digest:f����)
�����@K8��`��܋���_����\nsql_digest:Ko�=�c�|�^uyS5l),�1������
�h��" id="N36_0" fontsize=8 shape=box3d tooltip="0.02s"]
N36 -> N36_0 [label=" 0.02s" weight=100 tooltip="0.02s" labeltooltip="0.02s"]
N37 [label="executor\n(*executorBuilder)\nbuildBatchPointGet\n0.01s (0.14%)\nof 0.23s (3.32%)" id="node37" fontsize=12 shape=box tooltip="github.com/pingcap/tidb/pkg/executor.(*executorBuilder).buildBatchPointGet (0.23s)" color="#b2a794" fillcolor="#edebe9"]
N37_0 [label = "plan_digest:f����)
�����@K8��`��܋���_����\nsql_digest:Ko�=�c�|�^uyS5l),�1������
�h��" id="N37_0" fontsize=8 shape=box3d tooltip="0.01s"]
N37 -> N37_0 [label=" 0.01s" weight=100 tooltip="0.01s" labeltooltip="0.01s"]
N38 [label="executor\nResetContextOfStmt\n0.01s (0.14%)\nof 0.11s (1.59%)" id="node38" fontsize=12 shape=box tooltip="github.com/pingcap/tidb/pkg/executor.ResetContextOfStmt (0.11s)" color="#b2aea4" fillcolor="#edeceb"]
N38_0 [label = "plan_digest:f����)
�����@K8��`��܋���_����\nsql_digest:Ko�=�c�|�^uyS5l),�1������
�h��" id="N38_0" fontsize=8 shape=box3d tooltip="0.11s"]
N38 -> N38_0 [label=" 0.11s" weight=100 tooltip="0.11s" labeltooltip="0.11s"]
N39 [label="parser\nyyParse\n0.03s (0.43%)\nof 0.09s (1.30%)" id="node39" fontsize=15 shape=box tooltip="github.com/pingcap/tidb/pkg/parser.yyParse (0.09s)" color="#b2afa6" fillcolor="#edeceb"]
N40 [label="core\nlogicalOptimize\n0 of 0.12s (1.73%)" id="node40" fontsize=8 shape=box tooltip="github.com/pingcap/tidb/pkg/planner/core.logicalOptimize (0.12s)" color="#b2ada3" fillcolor="#edeceb"]
N41 [label="runtime\nmemclrNoHeapPointers\n0.04s (0.58%)" id="node41" fontsize=16 shape=box tooltip="runtime.memclrNoHeapPointers (0.04s)" color="#b2b1ad" fillcolor="#ededec"]
N42 [label="syscall\nSyscall6\n0.06s (0.87%)" id="node42" fontsize=17 shape=box tooltip="runtime/internal/syscall.Syscall6 (0.06s)" color="#b2b0aa" fillcolor="#edecec"]
N43 [label="exec\nOpen\n0.01s (0.14%)\nof 0.14s (2.02%)" id="node43" fontsize=12 shape=box tooltip="github.com/pingcap/tidb/pkg/executor/internal/exec.Open (0.14s)" color="#b2aca0" fillcolor="#edecea"]
N43_0 [label = "plan_digest:�▒,)5�֓
                                  �rW�qd�{Z���.▒(\nsql_digest:▒�zcZ����|�xتuK�3Ý�=;�[I�?" id="N43_0" fontsize=8 shape=box3d tooltip="0.01s"]
N43 -> N43_0 [label=" 0.01s" weight=100 tooltip="0.01s" labeltooltip="0.01s"]
N44 [label="runtime\n(*mspan)\nheapBitsSmallForAddr\n0.05s (0.72%)" id="node44" fontsize=17 shape=box tooltip="runtime.(*mspan).heapBitsSmallForAddr (0.05s)" color="#b2b1ac" fillcolor="#edecec"]
N45 [label="core\n(*Explain)\nprepareOperatorInfo\n0.01s (0.14%)\nof 0.08s (1.15%)" id="node45" fontsize=12 shape=box tooltip="github.com/pingcap/tidb/pkg/planner/core.(*Explain).prepareOperatorInfo (0.08s)" color="#b2afa8" fillcolor="#edeceb"]
N45_0 [label = "plan_digest:f����)
�����@K8��`��܋���_����\nsql_digest:Ko�=�c�|�^uyS5l),�1������
�h��" id="N45_0" fontsize=8 shape=box3d tooltip="0.08s"]
N45 -> N45_0 [label=" 0.08s" weight=100 tooltip="0.08s" labeltooltip="0.08s"]
N46 [label="session\nrunStmt\n0.01s (0.14%)\nof 0.55s (7.94%)" id="node46" fontsize=12 shape=box tooltip="github.com/pingcap/tidb/pkg/session.runStmt (0.55s)" color="#b2916b" fillcolor="#ede8e3"]
N46_0 [label = "plan_digest:f����)
�����@K8��`��܋���_����\nsql_digest:Ko�=�c�|�^uyS5l),�1������
�h��" id="N46_0" fontsize=8 shape=box3d tooltip="0.01s"]
N46 -> N46_0 [label=" 0.01s" weight=100 tooltip="0.01s" labeltooltip="0.01s"]
N47 [label="runtime\nfindRunnable\n0.01s (0.14%)\nof 0.13s (1.88%)" id="node47" fontsize=12 shape=box tooltip="runtime.findRunnable (0.13s)" color="#b2ada1" fillcolor="#edecea"]
N48 [label="runtime\n(*mspan)\ntypePointersOfUnchecked\n0.02s (0.29%)\nof 0.07s (1.01%)" id="node48" fontsize=14 shape=box tooltip="runtime.(*mspan).typePointersOfUnchecked (0.07s)" color="#b2b0a9" fillcolor="#edeceb"]
N49 [label="core\ngetStatsTable\n0.01s (0.14%)\nof 0.07s (1.01%)" id="node49" fontsize=12 shape=box tooltip="github.com/pingcap/tidb/pkg/planner/core.getStatsTable (0.07s)" color="#b2b0a9" fillcolor="#edeceb"]
N49_0 [label = "plan_digest:f����)
�����@K8��`��܋���_����\nsql_digest:Ko�=�c�|�^uyS5l),�1������
�h��" id="N49_0" fontsize=8 shape=box3d tooltip="0.07s"]
N49 -> N49_0 [label=" 0.07s" weight=100 tooltip="0.07s" labeltooltip="0.07s"]
N50 [label="session\n(*session)\ndoCommit\n0.02s (0.29%)\nof 0.06s (0.87%)" id="node50" fontsize=14 shape=box tooltip="github.com/pingcap/tidb/pkg/session.(*session).doCommit (0.06s)" color="#b2b0aa" fillcolor="#edecec"]
N51 [label="session\nrunStmt\n0 of 0.08s (1.15%)" id="node51" fontsize=8 shape=box tooltip="github.com/pingcap/tidb/pkg/session.runStmt (0.08s)" color="#b2afa8" fillcolor="#edeceb"]
N51_0 [label = "sql_digest:�
                            s�=}����GK%#��#f�@�QV�$BV�" id="N51_0" fontsize=8 shape=box3d tooltip="0.08s"]
N51 -> N51_0 [label=" 0.08s" weight=100 tooltip="0.08s" labeltooltip="0.08s"]
N52 [label="runtime\nmemclrNoHeapPointers\n0.04s (0.58%)" id="node52" fontsize=16 shape=box tooltip="runtime.memclrNoHeapPointers (0.04s)" color="#b2b1ad" fillcolor="#ededec"]
N52_0 [label = "plan_digest:�▒,)5�֓
                                  �rW�qd�{Z���.▒(\nsql_digest:▒�zcZ����|�xتuK�3Ý�=;�[I�?" id="N52_0" fontsize=8 shape=box3d tooltip="0.04s"]

We are using sqlDigest bytes directly in the label 😠 . It should be replaced by using the hex string.

[crazycs520]

Could you add more detail about how to reproduce it? Since I can't reproduce it.

BTW, normally, since

tidb/pkg/util/cpuprofile/pprof_api.go

Lines 184 to 192 in 318e82b

	func (*Collector) removeLabel(profileData *profile.Profile) {
	for _, s := range profileData.Sample {
	for k := range s.Label {
	if k != labelSQL {
	delete(s.Label, k)
	}
	}
	}
	}

, then the profile shouldn't contain the label which label name is not sql.