[BUG] “Distributed Tracing - Cloud” 这个grafana视图，无法生成火焰图

[yujianweilai]

Search before asking

• I had searched in the issues and found no similar feature requirement.

DeepFlow Component

Server

What you expected to happen

通过traceid，在“Distributed Tracing - Cloud” 这个grafana视图查询出链路追踪数据后，点击traceid，火焰图经过长时间的等待后，无法生成，如下图：

查询火焰图的“inspect -> data”，没有数据：

How to reproduce

No response

DeepFlow version

[root@pretycx-master1 ~]# kubectl exec -it -n deepflow deploy/deepflow-server -- deepflow-server -v
Name: deepflow-server community edition
Branch: v6.6.6
CommitID: 36ec980
RevCount: 11234
Compiler: go version go1.21.13 linux/amd64
CompileTime: 2024-10-25 09:20:12
[root@pretycx-master1 ~]# kubectl exec -it -n deepflow ds/deepflow-agent -- deepflow-agent -v
11227-d5e26dd2618cf3dbac2c10594d06d75aab3a38e1
Name: deepflow-agent community edition
Branch: v6.6.6
CommitId: d5e26dd
RevCount: 11227
Compiler: rustc 1.77.1 (7cf61ebde 2024-03-27)
CompileTime: 2024-10-11 07:20:14
[root@pretycx-master1 ~]#

DeepFlow agent list

Kubernetes CNI

k8s 1.19.16
calico

Operation-System/Kernel version

[root@pretycx-master1 ~]# awk -F '=' '/PRETTY_NAME/ { print $2 }' /etc/os-release
"CentOS Linux 7 (Core)"
[root@pretycx-master1 ~]# uname -r
3.10.0-1062.el7.x86_64
[root@pretycx-master1 ~]#

Anything else

No response

Are you willing to submit a PR?

• Yes I am willing to submit a PR!

Code of Conduct

• I agree to follow this project's Code of Conduct

[taloric]

@yujianweilai 先看下 deepflow-app 的镜像版本（镜像 tag 即可）

[yujianweilai]

@yujianweilai 先看下 deepflow-app 的镜像版本（镜像 tag 即可）
@taloric
registry.cn-beijing.aliyuncs.com/deepflow-ce/deepflow-app:v6.6.6

[taloric]

@yujianweilai 先看下 deepflow-app 的镜像版本（镜像 tag 即可）
@taloric
registry.cn-beijing.aliyuncs.com/deepflow-ce/deepflow-app:v6.6.6

@yujianweilai ok，可以更新到 latest 看看，在下面这个 commit 里修了可能有环的问题，可以看看是否已修复
deepflowio/deepflow-app@234374d

[yujianweilai]

@yujianweilai 先看下 deepflow-app 的镜像版本（镜像 tag 即可）
@taloric
registry.cn-beijing.aliyuncs.com/deepflow-ce/deepflow-app:v6.6.6

@yujianweilai ok，可以更新到 latest 看看，在下面这个 commit 里修了可能有环的问题，可以看看是否已修复 deepflowio/deepflow-app@234374d

@taloric 好的，谢谢。我先更新一下看看。可能需要观察一下，这个bug不是稳定复现的。

[yujianweilai]

@yujianweilai 先看下 deepflow-app 的镜像版本（镜像 tag 即可）
@taloric
registry.cn-beijing.aliyuncs.com/deepflow-ce/deepflow-app:v6.6.6

@yujianweilai ok，可以更新到 latest 看看，在下面这个 commit 里修了可能有环的问题，可以看看是否已修复 deepflowio/deepflow-app@234374d

@taloric
现在绘制火焰图失败的情况暂时没发现，但是绘制出的火焰图都是凌乱的，没法使用。。。。

[taloric]

@yujianweilai 这里可以确认下是否左右两边的数据都是 OTel？且有同一个 trace_id？
如果是这样， 应该就是两边（可能是两边服务过了多个不同的主机或集群）的时间差太大了，导致虽然有关联、但按真实时间显示相差较大

[yujianweilai]

@yujianweilai 这里可以确认下是否左右两边的数据都是 OTel？且有同一个 trace_id？ 如果是这样， 应该就是两边（可能是两边服务过了多个不同的主机或集群）的时间差太大了，导致虽然有关联、但按真实时间显示相差较大

@taloric 抱歉，刚才是我查询的问题，我选择了一些异步的业务进行查询，导致火焰图比较分散。但是我有个疑问，为何一次链路调用，时间跨度能有169s？我们的业务系统不应该有这么大的延时。如下图：

[taloric]

@yujianweilai 可以看看左下角的缩略图，粗看之下应该是从最初到最后的时间跨度有169s，此类情况可看下是否也是异步，一般而言：如果整个链路都有同一个 trace_id，他们一定会渲染在一张火焰图上 ，如果发生了异步使得【正常业务已经结束】、【异步任务隔一段时间后才被调度，但同样会产生 trace_id】，那他们可能就会出现这种相隔很远但在一张图上的现象。
我看您截图的数据都是 OTel，看上去应该就是这个现象（都是一个 trace_id）

[yujianweilai]

@yujianweilai 可以看看左下角的缩略图，粗看之下应该是从最初到最后的时间跨度有169s，此类情况可看下是否也是异步，一般而言：如果整个链路都有同一个 trace_id，他们一定会渲染在一张火焰图上 ，如果发生了异步使得【正常业务已经结束】、【异步任务隔一段时间后才被调度，但同样会产生 trace_id】，那他们可能就会出现这种相隔很远但在一张图上的现象。 我看您截图的数据都是 OTel，看上去应该就是这个现象（都是一个 trace_id）

@taloric 懂了，那应该是您分析的这个原因。
我的另外一个问题是，这种空行，程序上或者部署上如何改造才能弥补呢 ？

[taloric]

@yujianweilai
从您的这个截图来分析，初步看，黄色的 span 是 ingress，蓝色的是 gateway，绿色的是后端应用
且，空行之前没有做 OTel 插桩之类的行为（都是 S+N span），在到达 gateway 之后才开始发生插桩

此类情况一般而言原因是这样的：
空行的产生原因为空行的 【上下两行】没有明确的关联关系（如 parent_span_id => span_id），但又由于在上游注入了全局的 trace_id，使得虽然出现在一张图，但是上下无法关联（可以简单地理解为程序分析出了两个火焰图，但强行渲染在一起）

所以，解决这个问题只需要让空行上下有可用的关联关系即可。可以试试这样：
由于您在 gateway 之前的链路里也传入了 trace_id，可以用同样的方法传入 span_id，让 gateway 能集成 span_id 并生成 App Span 的 trace_id（比如假设 trace header 是 traceparent，遵循 w3c 的标准从 ingress 开始传入一个完整的 trace header 即可）
相关代码：https://github.com/deepflowio/deepflow-app/blob/main/app/app/application/l7_flow_tracing.py#L1779

另外，如果 gateway 可以修改为单线程模式 之类的模式，也可以使得空行下的 A Span 上下的两个 S span(server) 与 S span (client) 的 syscall_trace_id 有关联，也可关联上；
相关代码：https://github.com/deepflowio/deepflow-app/blob/main/app/app/application/l7_flow_tracing.py#L1819

[yujianweilai]

@yujianweilai 从您的这个截图来分析，初步看，黄色的 span 是 ingress，蓝色的是 gateway，绿色的是后端应用 且，空行之前没有做 OTel 插桩之类的行为（都是 S+N span），在到达 gateway 之后才开始发生插桩

此类情况一般而言原因是这样的： 空行的产生原因为空行的 【上下两行】没有明确的关联关系（如 parent_span_id => span_id），但又由于在上游注入了全局的 trace_id，使得虽然出现在一张图，但是上下无法关联（可以简单地理解为程序分析出了两个火焰图，但强行渲染在一起）

所以，解决这个问题只需要让空行上下有可用的关联关系即可。可以试试这样： 由于您在 gateway 之前的链路里也传入了 trace_id，可以用同样的方法传入 span_id，让 gateway 能集成 span_id 并生成 App Span 的 trace_id（比如假设 trace header 是 traceparent，遵循 w3c 的标准从 ingress 开始传入一个完整的 trace header 即可） 相关代码：https://github.com/deepflowio/deepflow-app/blob/main/app/app/application/l7_flow_tracing.py#L1779

另外，如果 gateway 可以修改为单线程模式 之类的模式，也可以使得空行下的 A Span 上下的两个 S span(server) 与 S span (client) 的 syscall_trace_id 有关联，也可关联上； 相关代码：https://github.com/deepflowio/deepflow-app/blob/main/app/app/application/l7_flow_tracing.py#L1819

@taloric 我们这套程序的插装情况是这样的：
我们的后端应用（cx开头的服务），容器里都使用了skywalking-agent进行插装，trace_id也是借助skywalking-agent产生的，除此之外，k8s的ingress没有集成skywalking-agent，没做任何插装。为了使用deepflow，也为了减少研发层面的改造，我在所有主机上部署了otel-collector+deepflow-agent，这样业务的trace信息的数据流就成了 skywalking-agent -> otel-collector->deepflow-agent -> deepflow-server这样。
所以，您提到“由于您在 gateway 之前的链路里也传入了 trace_id” ，但实际gateway服务前面就是ingress-nginx了，这个组件我们直接用了k8s官方的默认配置，并能没有集成什么插装工具，它是怎么能和其他链路出现在一张火焰图中呢？ 我看ingress的relatd data里，也没有携带traceid信息，如下图：

[taloric]

@yujianweilai
ok，右下角的 related data 里其实有几个关键字段：trace_id/[parent_]span_id/x_request_id/tcp_seq / syscall_trace_id，可以点击下空行之上没有 trace_id 的几个 span，看下具体是哪些字段相等（关键是可以找下空行前的 span 与空行后的 span 是通过什么信息关联上的，已经关联上没有空行的可以不用管）

这里 related_data 里每一列数据点击会闪烁显示关联的 span，可以这样操作：1. 先点击空行前的一个 S span ，2. 点击右下角的 related_data，找到在空行后闪烁的 span，看下它俩的关联信息

按我理解，这里一般是 syscall_trace_id 相等或启用了 x_request_id 注入，所以才会关联在一张图里，可以看下是否如此

[yujianweilai]

@yujianweilai ok，右下角的 related data 里其实有几个关键字段：trace_id/[parent_]span_id/x_request_id/tcp_seq / syscall_trace_id，可以点击下空行之上没有 trace_id 的几个 span，看下具体是哪些字段相等（关键是可以找下空行前的 span 与空行后的 span 是通过什么信息关联上的，已经关联上没有空行的可以不用管）

这里 related_data 里每一列数据点击会闪烁显示关联的 span，可以这样操作：1. 先点击空行前的一个 S span ，2. 点击右下角的 related_data，找到在空行后闪烁的 span，看下它俩的关联信息

按我理解，这里一般是 syscall_trace_id 相等或启用了 x_request_id 注入，所以才会关联在一张图里，可以看下是否如此

@taloric 非常感谢您的回复。安装您的建议，我做了查询，为方便理解，我录制了短视频，如下：

1. 查看空行之前的span，他们之间是通过什么字段关联的。我查到的结果是，related data中，他们的x_request_id_0 req_tcp_seq resp_tcp_seq 三个属性是对应相等的。见视频1
   1.zip

2. 查看空行前的 span 与空行后的 span 是通过什么信息关联上的。结果是我观察他们的related data，没有找到能关联的数据，见视频2
   2.zip

[yujianweilai]

总结一下沟通的结论：

1. 空行上面的span，虽然没有traceid，但都有相同的x_request_id字段；空行下面的span同时有traceid和x_request_id，所以它通过x_request_id与空行上面的span进行关联，最终呈现在一张火焰图中。
2. ingress-nginx组件，虽然本身没有插桩，但是因为其x-request-id字段默认是开启的（https://kubernetes.github.io/ingress-nginx/user-guide/nginx-configuration/configmap/），所以被deepflow-agent捕获到x-request-id，进而加入到了火焰图中。
3. 中间的空行，后期deepflow产品会进行优化改进。
4. java程序链接其他第三方组件，如 ：redis 、es等，因为使用的是java线程池，所以无法准确定位调用这些组件时的链路信息，除非组件支持类似“sql增加注释”的方式（https://deepflow.io/docs/zh/features/l7-protocols/sql/），将trace信息写入注释，这样deepflow-agent就能解析。
   

[yujianweilai]

@taloric 研发老师，关于上午我们讨论的mysql服务支持traceid注释的问题，我这边发现，有的服务，在生成mysql查询时，可以关联到mysql查询时网卡的转换信息（TID=089cfa2ac75c4a2b960a36c45fb3c048.128.17302791000245237），如下图：

但是有的链路，就关联不到mysql数据库网卡信息(TID=ef067c1423364f508b0f41d9ee764f86.111.17302785932343331)，如下：

这是什么原因？

[yujianweilai]

@taloric
您好。我当前的系统，昨天发现有一条链路信息，从“Distributed Tracing - Cloud”中可以查到链路明细，但是无法绘制出火焰图，如下图：

我尝试了重新登陆grafana重新查询，依旧不行。ck数据库的日志，我附上了
deepflow_deepflow-clickhouse-0_clickhouse (2).log
我重新做了一条业务，用新产生的traceid查询，是可以绘制出火焰图的，说明ck数据库本身工作是正常的。
还请研发老师协助排查一下问题，谢谢。

[taloric]

@taloric 您好。我当前的系统，昨天发现有一条链路信息，从“Distributed Tracing - Cloud”中可以查到链路明细，但是无法绘制出火焰图，如下图： 我尝试了重新登陆grafana重新查询，依旧不行。ck数据库的日志，我附上了 deepflow_deepflow-clickhouse-0_clickhouse (2).log 我重新做了一条业务，用新产生的traceid查询，是可以绘制出火焰图的，说明ck数据库本身工作是正常的。 还请研发老师协助排查一下问题，谢谢。

@yujianweilai 这里先看下 deepflow-app pod 日志
以及，报错里的这个参数可以直接通过 /v1/stats/L7Flowtracing 接口来请求 deepflow-app 重现问题，不用看 ck 了，应该不是数据库问题

[yujianweilai]

@taloric 您好。我当前的系统，昨天发现有一条链路信息，从“Distributed Tracing - Cloud”中可以查到链路明细，但是无法绘制出火焰图，如下图： 我尝试了重新登陆grafana重新查询，依旧不行。ck数据库的日志，我附上了 deepflow_deepflow-clickhouse-0_clickhouse (2).log 我重新做了一条业务，用新产生的traceid查询，是可以绘制出火焰图的，说明ck数据库本身工作是正常的。 还请研发老师协助排查一下问题，谢谢。

@yujianweilai 这里先看下 deepflow-app pod 日志 以及，报错里的这个参数可以直接通过 /v1/stats/L7Flowtracing 接口来请求 deepflow-app 重现问题，不用看 ck 了，应该不是数据库问题

@taloric
这是deepflow-app日志
deepflow_deepflow-app-848d9cf46-sz7wq_deepflow-app.log

[yujianweilai]

@taloric
日志中的错误信息：
Query UUID: 0b211835-707c-4465-bb88-0f65dced5d69 | Database: flow_log@deepflow-server | SQL: SELECT
type, signal_source, req_tcp_seq, resp_tcp_seq, toUnixTimestamp64Micro(start_time) AS start_time_us,
toUnixTimestamp64Micro(end_time) AS end_time_us, vtap_id, syscall_trace_id_request,
syscall_trace_id_response, span_id, parent_span_id, l7_protocol, trace_id, x_request_id_0,
x_request_id_1, _id, tap_side
FROM l7_flow_log
WHERE ((time>=1730251733 AND time<=1730338133) AND ((req_tcp_seq IN (3263209245) OR resp_tcp_seq IN (2871083224)) OR (syscall_trace_id_request IN (593758181830330528,161412617678996395,17297429615732103,161412617589083179) OR syscall_trace_id_response IN (593758181830330528,161412617678996395,17297429615732103,161412617589083179)))) limit 100
| Error:
list index out of range
Traceback (most recent call last):
File "/root/app/common/utils.py", line 105, in wrapper
response = await function(*args, **kwargs)
File "/root/app/application/application.py", line 26, in application_log_l7_tracing
status, response, failed_regions = await L7FlowTracing(
File "/root/app/application/l7_flow_tracing.py", line 204, in query
rst = await self.trace_l7_flow(
File "/root/app/application/l7_flow_tracing.py", line 560, in trace_l7_flow
l7_flows_merged, networks, flow_index_to_id0, related_flow_index_map, host_clock_correction, instance_to_agent = sort_all_flows(
File "/root/app/application/l7_flow_tracing.py", line 2238, in sort_all_flows
process_span_map = _union_app_spans(
File "/root/app/application/l7_flow_tracing.py", line 2317, in _union_app_spans
split_result = sp_span_pss.split_to_multiple_process_span_set()
File "/root/app/application/l7_flow_tracing.py", line 1734, in split_to_multiple_process_span_set
disjoint_set.get(i)
File "/root/app/common/disjoint_set.py", line 27, in get
return self._get(index, index)
File "/root/app/common/disjoint_set.py", line 22, in _get
root_index = self._get(self.disjoint_set[index], start_index)
File "/root/app/common/disjoint_set.py", line 15, in _get
if self.disjoint_set[index] in [-1, index, start_index]:

我用sql去数据库查询，确认是可以正常检索的，所以会不会是python代码的问题?

[taloric]

@yujianweilai 不用看 ck ，是一个 bug
在： deepflowio/deepflow-app#301 中修复。且昨日提到的空行问题也在此 PR 中体现

[yujianweilai]

@taloric 您好。我当前的系统，昨天发现有一条链路信息，从“Distributed Tracing - Cloud”中可以查到链路明细，但是无法绘制出火焰图，如下图： 我尝试了重新登陆grafana重新查询，依旧不行。ck数据库的日志，我附上了 deepflow_deepflow-clickhouse-0_clickhouse (2).log 我重新做了一条业务，用新产生的traceid查询，是可以绘制出火焰图的，说明ck数据库本身工作是正常的。 还请研发老师协助排查一下问题，谢谢。

@taloric 这个问题 您再给看看 谢谢

[taloric]

@yujianweilai 就在上面提及的 PR 里修复了，用 deepflow-app 最新镜像更新下即可

[Fancyki1]

@taloric v6.5版本能否同步修复一下，deepflowio/deepflow-app#301

[taloric]

@Fancyki1 done，可通过 v6.5 这个 tag 在 v6.5 获取到此修改对应的镜像

[yujianweilai]

@taloric
我刚才又确认了一下 deepflowio/deepflow-app#301 里，提到的“别场景还存在“断行”的情况”。
traceid=ef067c1423364f508b0f41d9ee764f86.125.17307081665506201 ，火焰图截图如下：

另外，我再附上sql的查询截图，您看一下我的sql是否正确。另外，我重新导出一份cvs，您再看看

l7_flow_log_202411051547.csv

总的来说，针对traceid=ef067c1423364f508b0f41d9ee764f86.125.17307081665506201 目前我这里看到的火焰图，确实是断行分散的，如果有需要，我们可以腾讯会议一下。

[yujianweilai]

研发老师：
我用了最新的v6.6.8版本部署了Deepflow，使用“Distributed Tracing”时，还是会有断行的情况，印象中这个问题该问题已经修复过了。如下图：

traceid=f8a681ae1af04040b859802a96b782bf.139.17337978473844185
我导出了csv数据文件，便于你们复现问题，Request List-data-2024-12-10 10_51_35.csv

另外，截图中有一个cx-im-processor服务，他的start_time是10:30:45，其他span都是10:30:47开始，导致这条span在绘制时，明显长于其他span

从nginx入口看，这条业务的开始时间就是10:30:47，为什么会出现10:30:45为开始时间的span呢 ？

@taloric @jeffrey4l @oilbeater

[taloric]

@yujianweilai
场景不一定是同一个。这里需要明确下：断线是因为找到了 trace_id 作为关联条件，但是没有 span_id 一类的父子关联条件，所以只能渲染在一张图上，但是没有明确的关联关系

在图里这个场景里，我看都是独立的 kafka 事件，互相异步发生，所以没有关联关系（也就是上下不构成父子关系），逻辑上看应该是对的

最后这个 10:30:45 的问题，这是一个 AppSpan，也就是它由 sdk 创建并发出，那它的时间其实只取决于 sdk 创建 span 时获取到的时间（也就是应用所在主机的时间），可能可以排查下是否这个主机的时间会早些