Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

连续请求情况下某些span会缺少duration属性 #19

Closed
jjtyro opened this issue Jul 3, 2018 · 13 comments
Closed

连续请求情况下某些span会缺少duration属性 #19

jjtyro opened this issue Jul 3, 2018 · 13 comments
Assignees
Labels
enhancement New feature or request
Milestone

Comments

@jjtyro
Copy link
Contributor

jjtyro commented Jul 3, 2018

  • 服务端
    sofa-tracer-sample-with-zipkin : sofa-tracer samples中的Demo
  • 测试场景
    连续使用curl发送请求:
for i in {1..100}
do
    curl -v 127.0.0.1:8080/zipkin?name="forkme"
done
  • 错误现象
    1.zipkin接收端的SkyWalking日志报错,因为在取duration属性时取到了空指针;
    2.使用工具截取网络包,发现某些span少掉了duration属性。
    下面是格式化后的局部报文内容,第二个span少了duration属性(应该是第二个trace吧):
 {
    "traceId": "003660b9d81d1dba",
    "id": "af63ad4c86019caf",
    "name": "http://127.0.0.1:8080/zipkin",
    "timestamp": 1530600005337000,
    "duration": 1000,
    "annotations": [
      {
        "timestamp": 1530600005337000,
        "value": "sr",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "timestamp": 1530600005338000,
        "value": "ss",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "current.thread.name",
        "value": "http-nio-8080-exec-3",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "local.app",
        "value": "SOFATracerReportZipkin",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "method",
        "value": "GET",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "req.size.bytes",
        "value": "-1",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "request.url",
        "value": "http://127.0.0.1:8080/zipkin",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "resp.size.bytes",
        "value": "52",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "result.code",
        "value": "200",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "span.kind",
        "value": "server",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      }
    ]
  },
  {
    "traceId": "003660b9d820ee4b",
    "id": "af63ad4c86019caf",
    "name": "http://127.0.0.1:8080/zipkin",
    "timestamp": 1530600005362000,
    "annotations": [
      {
        "timestamp": 1530600005362000,
        "value": "sr",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "timestamp": 1530600005362000,
        "value": "ss",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "current.thread.name",
        "value": "http-nio-8080-exec-5",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "local.app",
        "value": "SOFATracerReportZipkin",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "method",
        "value": "GET",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "req.size.bytes",
        "value": "-1",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "request.url",
        "value": "http://127.0.0.1:8080/zipkin",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "resp.size.bytes",
        "value": "52",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "result.code",
        "value": "200",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      },
      {
        "key": "span.kind",
        "value": "server",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "127.0.1.1"
        }
      }
    ]
  },
@guanchao-yang
Copy link
Member

zipkin接收端的 SkyWalking 日志报错,因为在取duration属性时取到了空指针;

@jjtyro 你好,具体是如何使用 SkyWalking 的哈。

@jjtyro
Copy link
Contributor Author

jjtyro commented Jul 3, 2018

在尝试SkyWalking的zipkin receiver,这个问题与后面是不是SkyWalking没有关系。

@guanchao-yang
Copy link
Member

@jjtyro 好的。我来看下,之后给你同步结论。

@guanchao-yang guanchao-yang self-assigned this Jul 3, 2018
@jjtyro
Copy link
Contributor Author

jjtyro commented Jul 3, 2018

@guanchao-yang Ok!

@guanchao-yang
Copy link
Member

guanchao-yang commented Jul 3, 2018

@jjtyro 非常抱歉,虽然按照你的方法,我还是没有能够复现出的场景。通过部署的 Zipkin 服务端,随机选择几个上报的 Span,类似如下图所示:

image

然后,选择汇报的数据格式即 json,会有类似如下的显示:

[
  {
    "traceId": "003660e8adb90f84",
    "id": "af63ad4c86019caf",
    "name": "http://127.0.0.1:8080/zipkin",
    "timestamp": 1530620120564000,
    "duration": 1000,
    "annotations": [
      {
        "timestamp": 1530620120564000,
        "value": "sr",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "10.15.233.42"
        }
      },
      {
        "timestamp": 1530620120565000,
        "value": "ss",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "10.15.233.42"
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "current.thread.name",
        "value": "http-nio-8080-exec-3",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "10.15.233.42"
        }
      },
      {
        "key": "local.app",
        "value": "SOFATracerReportZipkin",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "10.15.233.42"
        }
      },
      {
        "key": "method",
        "value": "GET",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "10.15.233.42"
        }
      },
      {
        "key": "req.size.bytes",
        "value": "-1",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "10.15.233.42"
        }
      },
      {
        "key": "request.url",
        "value": "http://127.0.0.1:8080/zipkin",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "10.15.233.42"
        }
      },
      {
        "key": "resp.size.bytes",
        "value": "51",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "10.15.233.42"
        }
      },
      {
        "key": "result.code",
        "value": "200",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "10.15.233.42"
        }
      },
      {
        "key": "span.kind",
        "value": "server",
        "endpoint": {
          "serviceName": "http://127.0.0.1:8080/zipkin",
          "ipv4": "10.15.233.42"
        }
      }
    ]
  }
]

发现其 duration 属性值是都存在的 "duration": 1000,,同时我们的 OpenTracing Span 到 zipkin.Span 的模型转化代码位置在:com.alipay.sofa.tracer.boot.zipkin.ZipkinSofaTracerSpanRemoteReporter#convertToZipkinSpan 具体的代码为:

// Zipkin is in nanosecond
zipkinSpanBuilder.duration((sofaTracerSpan.getEndTime() - sofaTracerSpan.getStartTime()) * 1000);
  • @jjtyro 你可以尝试将断点等打在这里,看下是不是真的缺失哈。如果是,麻烦在明确给我下复现方法哈,第一时间帮你解决,抱歉哈。

@jjtyro
Copy link
Contributor Author

jjtyro commented Jul 4, 2018

我这边是出现这种状况的,环境:

  • Sofa-tracer sample是跑在本地笔记本上,Skywalking是在远端服务器上
  • json包内容是通过wireshark截取tcp报文得到,不是在APM端界面导出
  • 笔记本环境是Ubuntu 16.04、Oracle jdk 1.8.0_171
  • sample代码在Idea IDE时run起来

每次通过上述shell脚本发送请求,都会产生这种效果。我更新下Sofa-tracer的代码,在你说的地方加日志,再看看。

@guanchao-yang
Copy link
Member

@jjtyro 好的,有问题第一时间反馈到我哈。

@jjtyro
Copy link
Contributor Author

jjtyro commented Jul 4, 2018

@guanchao-yang 通过加日志确认了,如果耗时是0, 即sofaTracerSpan.getEndTime()、sofaTracerSpan.getStartTime()值相等时,zipkin的Builder最终不会输出duration.
zipkin.Span.Builder:

public Span.Builder duration(@Nullable Long duration) {
            this.duration = duration != null && duration == 0L ? null : duration;
            return this;
        }

zipkin.Span.toString 最后会调用到zipkin.internal.write(),里面有:

if (value.duration != null) {
                b.writeAscii(",\"duration\":").writeAscii(value.duration);
            }

Ok, 应该不是sofa的问题,接收端在某些运算处理时没对这种情况做判断。
谢谢!

@guanchao-yang
Copy link
Member

@jjtyro 👍赞

@jjtyro
Copy link
Contributor Author

jjtyro commented Jul 4, 2018

为什么sofa-tracer取毫秒级做stratTime与endTime,而不是直接取微秒级? 一次处理在毫秒内完成是完全可能的。

@guanchao-yang
Copy link
Member

@jjtyro 是可以取 微秒级 的,这个点可以作为我们 Feature 的一个增强,不知道你能否参与贡献进来哈。可以直接给我们 PR 哈。

@jjtyro
Copy link
Contributor Author

jjtyro commented Jul 4, 2018

@guanchao-yang I am trying....

@guanchao-yang
Copy link
Member

@jjtyro Good Job!!!!

@guanchao-yang guanchao-yang added the enhancement New feature or request label Jul 5, 2018
@guanchao-yang guanchao-yang added this to the 2.1.2 milestone Jul 5, 2018
@jjtyro jjtyro closed this as completed Jul 9, 2018
guanchao-yang added a commit that referenced this issue Oct 9, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request
Projects
None yet
Development

No branches or pull requests

2 participants