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

More precise timestamps by using nanos offsets where available #243

Merged
merged 1 commit into from
Sep 28, 2016

Conversation

codefromthecrypt
Copy link
Member

This change brings Brave into the best timestamp practice by doing the
following:

  • Fixes unsafe access to Span.startTick
  • Records Span.startTick when starting any span the local process owns
  • Ensures Span.timestamp/duration are not reported on spans the local process doesn't own
  • Uses nanos offsets where available for annotation timestamps

The above corrects the common misalignment of spans in the UI, where
within a local process, operations that vary on microsecond basis have
annotations that extend beyond the span duration.

See openzipkin/openzipkin.github.io#49

@codefromthecrypt
Copy link
Member Author

Here's a beautifully aligned microsecond precision trace, made with the pending okhttp interceptor.

screen shot 2016-09-28 at 12 07 55 am

[
  {
    "traceId": "e73635b3e7c1df4d",
    "id": "e73635b3e7c1df4d",
    "name": "get",
    "timestamp": 1474992370922000,
    "duration": 158169,
    "annotations": [
      {
        "timestamp": 1474992370922000,
        "value": "sr",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      },
      {
        "timestamp": 1474992371080169,
        "value": "ss",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "http.status_code",
        "value": "200",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      },
      {
        "key": "http.url",
        "value": "/api/v1/traces",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      }
    ]
  },
  {
    "traceId": "e73635b3e7c1df4d",
    "id": "2c2c48ed6dc4fb91",
    "name": "get-traces",
    "parentId": "e73635b3e7c1df4d",
    "timestamp": 1474992370948000,
    "duration": 121927,
    "binaryAnnotations": [
      {
        "key": "lc",
        "value": "ElasticsearchStorage",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      },
      {
        "key": "request",
        "value": "QueryRequest{serviceName=elasticsearch, spanName=null, annotations=[], binaryAnnotations={}, minDuration=null, maxDuration=null, endTs=1474992245496, lookback=3600000, limit=10}",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      }
    ]
  },
  {
    "traceId": "e73635b3e7c1df4d",
    "id": "72250d0541592509",
    "name": "search-spansaggregations",
    "parentId": "e73635b3e7c1df4d",
    "timestamp": 1474992371030000,
    "duration": 14945,
    "binaryAnnotations": [
      {
        "key": "lc",
        "value": "okhttp",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      }
    ]
  },
  {
    "traceId": "e73635b3e7c1df4d",
    "id": "a5482d613b612827",
    "name": "search-spans",
    "parentId": "e73635b3e7c1df4d",
    "timestamp": 1474992371048000,
    "duration": 7794,
    "binaryAnnotations": [
      {
        "key": "lc",
        "value": "okhttp",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      }
    ]
  },
  {
    "traceId": "e73635b3e7c1df4d",
    "id": "8db9d7bf1213856a",
    "name": "post",
    "parentId": "72250d0541592509",
    "timestamp": 1474992371035000,
    "duration": 9795,
    "annotations": [
      {
        "timestamp": 1474992371035000,
        "value": "cs",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      },
      {
        "timestamp": 1474992371044795,
        "value": "cr",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "http.url",
        "value": "http://localhost:9200/zipkin-2016-09-27/span/_search?ignore_unavailable=true&allow_no_indices=true&expand_wildcards=open",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      },
      {
        "key": "sa",
        "value": true,
        "endpoint": {
          "serviceName": "elasticsearch",
          "ipv4": "127.0.0.1",
          "port": 9200
        }
      }
    ]
  },
  {
    "traceId": "e73635b3e7c1df4d",
    "id": "4c3537b7a695a8cc",
    "name": "post",
    "parentId": "a5482d613b612827",
    "timestamp": 1474992371050000,
    "duration": 5904,
    "annotations": [
      {
        "timestamp": 1474992371050000,
        "value": "cs",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      },
      {
        "timestamp": 1474992371055904,
        "value": "cr",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "http.url",
        "value": "http://localhost:9200/zipkin-2016-09-27/span/_search?ignore_unavailable=true&allow_no_indices=true&expand_wildcards=open",
        "endpoint": {
          "serviceName": "zipkin-server",
          "ipv4": "192.168.99.1",
          "port": 9411
        }
      },
      {
        "key": "sa",
        "value": true,
        "endpoint": {
          "serviceName": "elasticsearch",
          "ipv4": "127.0.0.1",
          "port": 9200
        }
      }
    ]
  }
]

@@ -218,4 +241,8 @@ public long currentTimeMicroseconds() {
return System.currentTimeMillis() * 1000;
}
}

synchronized Long startTick(Span span) {
return span.startTick;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this be synchronizing on the span rather than this?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

another good catch. thanks!

This change brings Brave into the best timestamp practice by doing the
following:
* Fixes unsafe access to Span.startTick
* Records Span.startTick when starting any span the local process owns
* Ensures Span.timestamp/duration are not reported on spans the local process doesn't own
* Uses nanos offsets where available for annotation timestamps

The above corrects the common misalignment of spans in the UI, where
within a local process, operations that vary on microsecond basis have
annotations that extend beyond the span duration.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants