search

deepflowio / deepflow

eBPF Observability - Distributed Tracing and Profiling
https://deepflow.io
Apache License 2.0
2.98k stars 333 forks source link

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

Open yujianweilai opened 3 weeks ago

yujianweilai commented 3 weeks ago

Search before asking

DeepFlow Component

Server

What you expected to happen

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

c99436ed23c066932379a8f5a25c817 5d7c98b6afd2795f2612dad575e115b 350350b954f433435e55f4f58ac10b1

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

39ea60ffa72b3e804fbae8acf4cd7d2

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: 36ec980d0212c86f2dedbfba3f067d834b9a2fb1 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: d5e26dd2618cf3dbac2c10594d06d75aab3a38e1 RevCount: 11227 Compiler: rustc 1.77.1 (7cf61ebde 2024-03-27) CompileTime: 2024-10-11 07:20:14 [root@pretycx-master1 ~]#

DeepFlow agent list

image

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?

Code of Conduct

taloric commented 3 weeks ago

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

yujianweilai commented 3 weeks ago

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

taloric commented 3 weeks ago

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

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

yujianweilai commented 3 weeks ago

@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 commented 3 weeks ago

@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 现在绘制火焰图失败的情况暂时没发现，但是绘制出的火焰图都是凌乱的，没法使用。。。。 image

taloric commented 3 weeks ago

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

yujianweilai commented 3 weeks ago

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

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

taloric commented 3 weeks ago

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

yujianweilai commented 3 weeks ago

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

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

taloric commented 3 weeks ago

@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 commented 3 weeks ago

@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信息，如下图： image

taloric commented 3 weeks ago

@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 commented 3 weeks ago

@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 commented 3 weeks ago

总结一下沟通的结论：

  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就能解析。 image
yujianweilai commented 3 weeks ago

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

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

这是什么原因？

yujianweilai commented 3 weeks ago

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

taloric commented 3 weeks ago

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

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

yujianweilai commented 3 weeks ago

@taloric 您好。我当前的系统，昨天发现有一条链路信息，从“Distributed Tracing - Cloud”中可以查到链路明细，但是无法绘制出火焰图，如下图： image 我尝试了重新登陆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 commented 3 weeks ago

@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代码的问题? image

taloric commented 3 weeks ago

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

yujianweilai commented 3 weeks ago

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

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

taloric commented 3 weeks ago

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

Fancyki1 commented 3 weeks ago

@taloric v6.5版本能否同步修复一下，https://github.com/deepflowio/deepflow-app/pull/301

taloric commented 2 weeks ago

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

yujianweilai commented 2 weeks ago

@taloric 我刚才又确认了一下 https://github.com/deepflowio/deepflow-app/pull/301 里，提到的“别场景还存在“断行”的情况”。 traceid=ef067c1423364f508b0f41d9ee764f86.125.17307081665506201 ，火焰图截图如下： image 另外，我再附上sql的查询截图，您看一下我的sql是否正确。另外，我重新导出一份cvs，您再看看 image l7_flow_log_202411051547.csv

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