UI: Render bug? #1280

rogeralsing · 2016-09-08T22:38:12Z

I think there is a render bug in the UI.

I have this trace.
The root span and the first child span really ends at the same time, but still, the child span looks like it completes after the root span:

Here is the metrics of the root span

Completes at relative time 143 ms

Here are the metrics of the child span:

Completes at relative time 143 ms

When looking at the JSON, it looks strange, because they both have the same duration, but the child span has a later timestamp.

[
  {
    "traceId": "47e2e4369bcf4e7e",
    "id": "47e2e4369bcf4e7e",
    "name": "main",
    "timestamp": 1473373851242426, //first timestamp
    "duration": 143061,  //<----- same duration
  ...snip
  },
  {
    "traceId": "47e2e4369bcf4e7e",
    "id": "4234a32f8ace0f08",
    "name": "get /customers",
    "parentId": "47e2e4369bcf4e7e",
    "timestamp": 1473373851253406, //later timestamp
    "duration": 143061,  //<----- same duration

I have checked the code of the C# provider I'm using, and the timestamp and duration is never explicitly set. So I assume those values comes from the annotations when sending it to Zipkin?

Also, wouldnt it be good to show both the CS/CR and the SR/SS intervals in the UI?
so one can see when the call was issued from the client, and when the server started processing?
e.g. different colors of the bars or something..

To me it looks like the bar length is now calculated from the CS/CR interval, but the timestamp itself seems to be when the SR started.
Or am I misinterpreting this completely?

The text was updated successfully, but these errors were encountered:

codefromthecrypt · 2016-09-09T01:06:12Z

Hi, Roger. Can you click the JSON button and add that to the issue? It will help us figure out what's up.

…

-A

rogeralsing · 2016-09-09T05:53:26Z

Sure

[
  {
    "traceId": "48c1b3160196c098",
    "id": "48c1b3160196c098",
    "name": "main",
    "timestamp": 1473400356307624,
    "duration": 199117,
    "annotations": [
      {
        "timestamp": 1473400356307624,
        "value": "sr",
        "endpoint": {
          "serviceName": "client",
          "ipv4": "12.123.12.169",
          "port": 80
        }
      },
      {
        "timestamp": 1473400356506741,
        "value": "ss",
        "endpoint": {
          "serviceName": "client",
          "ipv4": "12.123.12.169",
          "port": 80
        }
      }
    ]
  },
  {
    "traceId": "48c1b3160196c098",
    "id": "48c898fd24ab75a4",
    "name": "get /customers",
    "parentId": "48c1b3160196c098",
    "timestamp": 1473400356318643,
    "duration": 199117,
    "annotations": [
      {
        "timestamp": 1473400356307624,
        "value": "cs",
        "endpoint": {
          "serviceName": "client",
          "ipv4": "12.123.12.169",
          "port": 80
        }
      },
      {
        "timestamp": 1473400356318643,
        "value": "sr",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      },
      {
        "timestamp": 1473400356493766,
        "value": "ss",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      },
      {
        "timestamp": 1473400356506741,
        "value": "cr",
        "endpoint": {
          "serviceName": "client",
          "ipv4": "12.123.12.169",
          "port": 80
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "Request",
        "value": "some payload",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      },
      {
        "key": "Result",
        "value": "some result",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      }
    ]
  },
  {
    "traceId": "48c1b3160196c098",
    "id": "406faffcd864013d",
    "name": "select orders",
    "parentId": "48c898fd24ab75a4",
    "timestamp": 1473400356452666,
    "duration": 52099,
    "annotations": [
      {
        "timestamp": 1473400356441667,
        "value": "cs",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      },
      {
        "timestamp": 1473400356452666,
        "value": "sr",
        "endpoint": {
          "serviceName": "orderdb",
          "ipv4": "1.0.0.127",
          "port": 1234
        }
      },
      {
        "timestamp": 1473400356483168,
        "value": "ss",
        "endpoint": {
          "serviceName": "orderdb",
          "ipv4": "1.0.0.127",
          "port": 1234
        }
      },
      {
        "timestamp": 1473400356493766,
        "value": "cr",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "sql.query",
        "value": "select * from Orders where OrderId = 123",
        "endpoint": {
          "serviceName": "orderdb",
          "ipv4": "1.0.0.127",
          "port": 1234
        }
      }
    ]
  },
  {
    "traceId": "48c1b3160196c098",
    "id": "46320d346edc5a84",
    "name": "select customers",
    "parentId": "48c898fd24ab75a4",
    "timestamp": 1473400356329640,
    "duration": 123024,
    "annotations": [
      {
        "timestamp": 1473400356318643,
        "value": "cs",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      },
      {
        "timestamp": 1473400356329640,
        "value": "sr",
        "endpoint": {
          "serviceName": "customerdb",
          "ipv4": "1.0.0.127",
          "port": 1234
        }
      },
      {
        "timestamp": 1473400356430668,
        "value": "ss",
        "endpoint": {
          "serviceName": "customerdb",
          "ipv4": "1.0.0.127",
          "port": 1234
        }
      },
      {
        "timestamp": 1473400356441667,
        "value": "cr",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "sql.query",
        "value": "select * from Customers where CustomerId = 123",
        "endpoint": {
          "serviceName": "customerdb",
          "ipv4": "1.0.0.127",
          "port": 1234
        }
      }
    ]
  }
]

codefromthecrypt · 2016-09-09T07:04:02Z

nit: the service logging "sr", "ss" is called "client". That means "client" is a server that received a request, and sent a response. I think that's probably wrong.

codefromthecrypt · 2016-09-09T07:07:51Z

the middle span 48c898fd24ab75a4 is very strange compared to its parent. It is unlikely a server can receive a request and send an outbound one with no overhead w/in the same microsecond. if it can.. I want one!

codefromthecrypt · 2016-09-09T07:12:25Z

so far.. I think there is a bug here. the span looks valid to me (even if unrealistic for a few spots, looks ok). I'm going to dig deeper into why the parent is offset.

rogeralsing · 2016-09-09T07:17:42Z

The lack of overhead is intentional just to see if there is any overhead to the C# provider, just to see that it doesnt introduce milliseconds latency on each request.
(Its all just fake data)

codefromthecrypt · 2016-09-09T07:30:00Z

ahh I think I found it. The timestamp is wrong on the second span.

codefromthecrypt · 2016-09-09T07:32:11Z

Span.timestamp is when the span began. This says that the first annotation ("cs") was written 11ms before the span began! You'll notice if you set the timestamp to the minimum, it renders properly

  {
    "traceId": "48c1b3160196c098",
    "id": "48c898fd24ab75a4",
    "name": "get /customers",
    "parentId": "48c1b3160196c098",
    "timestamp": 1473400356318643,
    "duration": 199117,
    "annotations": [
      {
        "timestamp": 1473400356307624,

codefromthecrypt · 2016-09-09T07:35:42Z

in general, span.timestamp and span.duration should be added when the host is authoritative for that span, ie. they started it.

For example, if you start a root span, then setting timestamp, duration is a good idea. It is also a good idea when you start a client span. However, if you are a server receiving a span that was started by a client, setting Span.timestamp, duration is likely invalid.

codefromthecrypt · 2016-09-09T08:35:11Z

added docs here, which should hopefully help others with the same problem openzipkin/openzipkin.github.io#46

rogeralsing · 2016-09-09T08:48:31Z

cc @Horusiath

Where does the timespan and duration come from?
From what I can see, its not set at all in the thrift payload:

        public static Span ToThrift(this Zipkin.Span span)
        {
            var s = new Span
            {
                TraceId = (long)span.TraceHeader.TraceId,
                Id = (long)span.TraceHeader.SpanId,
                Name = span.Name,
                Debug = span.TraceHeader.IsDebug,
               //No values provided for duration or timestamp
            };

            if (span.TraceHeader.ParentId.HasValue) s.ParentId = (long)span.TraceHeader.ParentId.Value;

            s.__isset.annotations = span.Annotations.Count != 0;
            foreach (var annotation in span.Annotations)
            {
                var thrifted = annotation.ToThrift();
                var ep = thrifted.__isset.host ? thrifted.Host : span.Endpoint.ToThrift();
                ep.ServiceName = span.ServiceName;
                thrifted.Host = ep;
                s.Annotations.Add(thrifted);
            }

            s.__isset.binary_annotations = span.BinaryAnnotations.Count != 0;
            foreach (var binaryAnnotation in span.BinaryAnnotations)
            {
                var thrifted = binaryAnnotation.ToThrift();
                var ep = thrifted.__isset.host ? thrifted.Host : span.Endpoint.ToThrift();
                ep.ServiceName = span.ServiceName;
                thrifted.Host = ep;
                s.BinaryAnnotations.Add(thrifted);
            }

            return s;
        }

So is it the Zipkin server that calculates and sets the timespan and duration or where does it come from?

[Edit] debugging the C# library I can verify that the Timestamp and duration for the span itself is not being set, nor written to the thrift stream.
So the values must come from the Zipkin server, which then incorrectly calculates them from the annotations? or?

codefromthecrypt · 2016-09-09T09:04:04Z

@rogeralsing thanks for looking into this. I'll check the logic on the server-side to see if it could have caused this.

codefromthecrypt · 2016-09-09T09:11:17Z

I believe it was a server problem in this case. #1281

codefromthecrypt · 2016-09-10T02:48:04Z

Can you try with zipkin 1.10? seems to calculate properly when instrumentation don't set timestamp/duration. Please re-open if it is a problem, still.

$ curl -vs 192.168.99.100:9411/api/v1/spans -H'Content-type: application/json' -H 'Expect:' -d '[
  {
    "traceId": "48c1b3160196c098",
    "id": "48c1b3160196c098",
    "name": "main",
    "annotations": [
      {
        "timestamp": 1473400356307624,
        "value": "sr",
        "endpoint": {
          "serviceName": "client",
          "ipv4": "12.123.12.169",
          "port": 80
        }
      },
      {
        "timestamp": 1473400356506741,
        "value": "ss",
        "endpoint": {
          "serviceName": "client",
          "ipv4": "12.123.12.169",
          "port": 80
        }
      }
    ]
  },
  {
    "traceId": "48c1b3160196c098",
    "id": "48c898fd24ab75a4",
    "name": "get /customers",
    "parentId": "48c1b3160196c098",
    "annotations": [
      {
        "timestamp": 1473400356307624,
        "value": "cs",
        "endpoint": {
          "serviceName": "client",
          "ipv4": "12.123.12.169",
          "port": 80
        }
      },
      {
        "timestamp": 1473400356318643,
        "value": "sr",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      },
      {
        "timestamp": 1473400356493766,
        "value": "ss",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      },
      {
        "timestamp": 1473400356506741,
        "value": "cr",
        "endpoint": {
          "serviceName": "client",
          "ipv4": "12.123.12.169",
          "port": 80
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "Request",
        "value": "some payload",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      },
      {
        "key": "Result",
        "value": "some result",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      }
    ]
  },
  {
    "traceId": "48c1b3160196c098",
    "id": "406faffcd864013d",
    "name": "select orders",
    "parentId": "48c898fd24ab75a4",
    "annotations": [
      {
        "timestamp": 1473400356441667,
        "value": "cs",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      },
      {
        "timestamp": 1473400356452666,
        "value": "sr",
        "endpoint": {
          "serviceName": "orderdb",
          "ipv4": "1.0.0.127",
          "port": 1234
        }
      },
      {
        "timestamp": 1473400356483168,
        "value": "ss",
        "endpoint": {
          "serviceName": "orderdb",
          "ipv4": "1.0.0.127",
          "port": 1234
        }
      },
      {
        "timestamp": 1473400356493766,
        "value": "cr",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "sql.query",
        "value": "select * from Orders where OrderId = 123",
        "endpoint": {
          "serviceName": "orderdb",
          "ipv4": "1.0.0.127",
          "port": 1234
        }
      }
    ]
  },
  {
    "traceId": "48c1b3160196c098",
    "id": "46320d346edc5a84",
    "name": "select customers",
    "parentId": "48c898fd24ab75a4",
    "annotations": [
      {
        "timestamp": 1473400356318643,
        "value": "cs",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      },
      {
        "timestamp": 1473400356329640,
        "value": "sr",
        "endpoint": {
          "serviceName": "customerdb",
          "ipv4": "1.0.0.127",
          "port": 1234
        }
      },
      {
        "timestamp": 1473400356430668,
        "value": "ss",
        "endpoint": {
          "serviceName": "customerdb",
          "ipv4": "1.0.0.127",
          "port": 1234
        }
      },
      {
        "timestamp": 1473400356441667,
        "value": "cr",
        "endpoint": {
          "serviceName": "fakewebapi",
          "ipv4": "1.0.0.127",
          "port": 9000
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "sql.query",
        "value": "select * from Customers where CustomerId = 123",
        "endpoint": {
          "serviceName": "customerdb",
          "ipv4": "1.0.0.127",
          "port": 1234
        }
      }
    ]
  }
]'

rogeralsing · 2016-09-10T15:55:58Z

It looks correct now, thanks!

codefromthecrypt · 2016-09-12T00:35:35Z

Whew.. thanks for checking back!

On 10 Sep 2016 23:56, "Roger Johansson" notifications@github.com wrote:

It looks correct now, thanks!

—
You are receiving this because you modified the open/close state.
Reply to this email directly, view it on GitHub
#1280 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAD6183FqN2Aay5GdzLEERqBf2cNwkf0ks5qotMPgaJpZM4J4hpJ
.

rogeralsing mentioned this issue Sep 9, 2016

Possible duration bug openzipkin-attic/zipkin-csharp#9

Open

codefromthecrypt mentioned this issue Sep 9, 2016

Adds overdue information about setting timestamps and duration openzipkin/openzipkin.github.io#46

Merged

codefromthecrypt mentioned this issue Sep 9, 2016

Stop adding timestamp and duration to spans at ingest #1281

Closed

codefromthecrypt closed this as completed Sep 10, 2016

codefromthecrypt added question ui Zipkin UI labels Oct 26, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

UI: Render bug? #1280

UI: Render bug? #1280

rogeralsing commented Sep 8, 2016 •

edited

Loading

codefromthecrypt commented Sep 9, 2016 via email

rogeralsing commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

rogeralsing commented Sep 9, 2016 •

edited

Loading

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

rogeralsing commented Sep 9, 2016 •

edited

Loading

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 10, 2016

rogeralsing commented Sep 10, 2016

codefromthecrypt commented Sep 12, 2016

UI: Render bug? #1280

UI: Render bug? #1280

Comments

rogeralsing commented Sep 8, 2016 • edited Loading

codefromthecrypt commented Sep 9, 2016 via email

rogeralsing commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

rogeralsing commented Sep 9, 2016 • edited Loading

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

rogeralsing commented Sep 9, 2016 • edited Loading

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 9, 2016

codefromthecrypt commented Sep 10, 2016

rogeralsing commented Sep 10, 2016

codefromthecrypt commented Sep 12, 2016

rogeralsing commented Sep 8, 2016 •

edited

Loading

rogeralsing commented Sep 9, 2016 •

edited

Loading

rogeralsing commented Sep 9, 2016 •

edited

Loading