Skip to content
This repository was archived by the owner on Jul 31, 2023. It is now read-only.

Remove call to time.Now() on worker thread when handling record reqs#1210

Merged
rghetia merged 1 commit intocensus-instrumentation:masterfrom
ian-mi:record-req-time
Jun 2, 2020
Merged

Remove call to time.Now() on worker thread when handling record reqs#1210
rghetia merged 1 commit intocensus-instrumentation:masterfrom
ian-mi:record-req-time

Conversation

@ian-mi
Copy link
Copy Markdown
Contributor

@ian-mi ian-mi commented Jun 1, 2020

Time is already recorded on the client side and stored in the currently unused recordReq.t
field. Avoiding these repeated calls to time.Now while the worker is blocked can significantly
reduce worker contention.

I observed the following results on the existing benchmarks with this change:

name                 old time/op    new time/op    delta
RecordReqCommand-16    2.91µs ± 4%    2.47µs ± 4%  -15.08%  (p=0.000 n=20+20)
RecordViaStats-16      3.52µs ± 5%    3.06µs ± 3%  -13.00%  (p=0.000 n=20+20)

name                 old alloc/op   new alloc/op   delta
RecordReqCommand-16      426B ± 0%      426B ± 0%     ~     (all equal)
RecordViaStats-16        634B ± 0%      634B ± 0%     ~     (all equal)

name                 old allocs/op  new allocs/op  delta
RecordReqCommand-16      25.0 ± 0%      25.0 ± 0%     ~     (all equal)
RecordViaStats-16        29.0 ± 0%      29.0 ± 0%     ~     (all equal)

In addition when profiling other benchmarks where worker contention proved to be a bottleneck I've observed cases where around half of the worker's time was spent calling time.Now(), e.g.:

(pprof) top view.*start -cum
Active filters:
   focus=view.*start
Showing nodes accounting for 3.75s, 10.45% of 35.90s total
Dropped 42 nodes (cum <= 0.18s)
Showing top 10 nodes out of 58
      flat  flat%   sum%        cum   cum%
         0     0%     0%      5.72s 15.93%  go.opencensus.io/stats/view.(*worker).start
     0.27s  0.75%  0.75%      5.03s 14.01%  go.opencensus.io/stats/view.(*recordReq).handleCommand
     0.18s   0.5%  1.25%      2.88s  8.02%  time.Now
     0.08s  0.22%  1.48%      2.70s  7.52%  time.now
     1.34s  3.73%  5.21%      1.41s  3.93%  runtime.walltime (inline)
     1.15s  3.20%  8.41%      1.21s  3.37%  runtime.nanotime (inline)
     0.03s 0.084%  8.50%      0.96s  2.67%  go.opencensus.io/stats/view.(*viewInternal).addSample
     0.58s  1.62% 10.11%      0.81s  2.26%  runtime.mapiternext
     0.03s 0.084% 10.19%      0.73s  2.03%  go.opencensus.io/stats/view.encodeWithKeys
     0.09s  0.25% 10.45%      0.69s  1.92%  runtime.selectgo

@ian-mi
Remove call to time.Now() on worker thread when handling record reqs
d6871ee 
Time is already recorded on the client side and stored in the currently unused recordReq.t
field. Avoiding these repeated calls to time.Now while the worker is blocked can significantly
reduce worker contention.
@ian-mi ian-mi requested review from a team, rakyll and rghetia as code owners June 1, 2020 20:15
@rghetia rghetia merged commit cd9ae5c into census-instrumentation:master Jun 2, 2020
evankanderson pushed a commit to evankanderson/opencensus-go that referenced this pull request Jun 4, 2020
@ian-mi @evankanderson
Remove call to time.Now() on worker thread when handling record reqs (c…
a5a78ff 
…ensus-instrumentation#1210)

Time is already recorded on the client side and stored in the currently unused recordReq.t
field. Avoiding these repeated calls to time.Now while the worker is blocked can significantly
reduce worker contention.
rghetia pushed a commit that referenced this pull request Jun 8, 2020
@evankanderson @ian-mi
Allow custom view.Meters to export metrics for other Resources (#1212)
1901b56 
* Remove call to time.Now() on worker thread when handling record reqs (#1210)

Time is already recorded on the client side and stored in the currently unused recordReq.t
field. Avoiding these repeated calls to time.Now while the worker is blocked can significantly
reduce worker contention.

* Update Meter to track and report Resource for metric data.

Co-authored-by: Ian Milligan <ianmllgn@gmail.com>
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Reviewers

@rakyll rakyll Awaiting requested review from rakyll

1 more reviewer

@rghetia rghetia rghetia approved these changes

Reviewers whose approvals may not affect merge requirements

Assignees

No one assigned

Labels

cla: yes

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

3 participants

@ian-mi @rghetia @googlebot