Commit Graph

7 Commits

Author SHA1 Message Date
Tonis Tiigi
c427ad74c6 trace: initialize templates lazily
Parsing the templates can take a significant amount of
time(30-35ms) so it should not be done on the init phase.

Change-Id: I8f258b8028510e698a97b55faeac0d28a61b7b22
Reviewed-on: https://go-review.googlesource.com/21654
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
2017-01-13 21:57:39 +00:00
Radu Berinde
f4b625ec9b trace: don't allocate all events upfront
SetMaxEvent allocates storage for all events, which is very expensive
if we want to set a high value; even with small values, the
unnecessary allocation of the initial slice is measurable.

We improve the performance by having a few events preallocated as part
of the trace, and appending as necessary. We also co-locate the flags
in event which makes it smaller (by a word).

We also add a set of benchmarks; before and after amortized cost
per-event is shown:

name                    old time/op  new time/op  delta
Trace_Default_2-32      1.19µs ± 1%  0.96µs ± 0%  -18.94%
Trace_Default_10-32      579ns ± 0%   635ns ± 1%   +9.82%
Trace_Default_100-32     463ns ± 1%   466ns ± 1%     ~
Trace_Default_1000-32    451ns ± 1%   451ns ± 0%     ~
Trace_Default_10000-32   451ns ± 2%   449ns ± 1%     ~
Trace_10_2-32           1.41µs ± 1%  0.96µs ± 1%  -31.74%
Trace_10_10-32           623ns ± 1%   634ns ± 1%   +1.73%
Trace_10_100-32          469ns ± 1%   466ns ± 1%     ~
Trace_10_1000-32         452ns ± 1%   453ns ± 2%     ~
Trace_10_10000-32        451ns ± 1%   449ns ± 1%     ~
Trace_100_2-32          2.78µs ± 2%  0.97µs ± 1%  -65.28%
Trace_100_10-32          912ns ± 1%   637ns ± 1%  -30.23%
Trace_100_100-32         479ns ± 1%   541ns ± 0%  +12.77%
Trace_100_1000-32        510ns ± 0%   541ns ± 1%   +6.08%
Trace_100_10000-32       514ns ± 1%   540ns ± 0%   +5.14%
Trace_1000_2-32         17.2µs ± 1%   1.0µs ± 1%  -94.39%
Trace_1000_10-32        3.90µs ± 1%  0.64µs ± 0%  -83.68%
Trace_1000_100-32        814ns ± 1%   542ns ± 0%  -33.46%
Trace_1000_1000-32       503ns ± 1%   581ns ± 0%  +15.56%
Trace_1000_10000-32     1.28µs ± 2%  1.03µs ± 1%  -19.68%

Change-Id: I5bbc12153a9f30dff821ef139583cb1c07a11069
Reviewed-on: https://go-review.googlesource.com/30615
Reviewed-by: Ian Lance Taylor <iant@golang.org>
Run-TryBot: Ian Lance Taylor <iant@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
2016-10-07 14:35:04 +00:00
Brad Fitzpatrick
9b4f494e78 Revert "trace: don't allocate all events upfront"
This reverts commit If7c68bb1809fb92fa5d06cb6640be5e09e1f131f.

Reason for revert: breaks the build for Go 1.6 or below due to use of Go 1.7+ only features.

Original change's description:
> trace: don't allocate all events upfront
> 
> SetMaxEvent allocates storage for all events, which is very expensive
> if we want to set a high value; even with small values, the
> unnecessary allocation of the initial slice is measurable.
> 
> We improve the performance by having a few events preallocated as part
> of the trace, and appending as necessary. We also co-locate the flags
> in event which makes it smaller (by a word).
> 
> We also add a set of benchmarks; before and after amortized cost
> per-event is shown:
> 
> name                 old time/op  new time/op  delta
> Trace/0-2-32         1.19µs ± 1%  0.96µs ± 0%  -18.94%  (p=0.008 n=5+5)
> Trace/0-10-32         579ns ± 0%   635ns ± 1%   +9.82%  (p=0.008 n=5+5)
> Trace/0-100-32        463ns ± 1%   466ns ± 1%     ~     (p=0.190 n=5+5)
> Trace/0-1000-32       451ns ± 1%   451ns ± 0%     ~     (p=0.984 n=5+5)
> Trace/0-10000-32      451ns ± 2%   449ns ± 1%     ~     (p=0.492 n=5+5)
> Trace/10-2-32        1.41µs ± 1%  0.96µs ± 1%  -31.74%  (p=0.008 n=5+5)
> Trace/10-10-32        623ns ± 1%   634ns ± 1%   +1.73%  (p=0.008 n=5+5)
> Trace/10-100-32       469ns ± 1%   466ns ± 1%     ~     (p=0.357 n=5+5)
> Trace/10-1000-32      452ns ± 1%   453ns ± 2%     ~     (p=0.913 n=5+5)
> Trace/10-10000-32     451ns ± 1%   449ns ± 1%     ~     (p=0.175 n=5+5)
> Trace/100-2-32       2.78µs ± 2%  0.97µs ± 1%  -65.28%  (p=0.008 n=5+5)
> Trace/100-10-32       912ns ± 1%   637ns ± 1%  -30.23%  (p=0.008 n=5+5)
> Trace/100-100-32      479ns ± 1%   541ns ± 0%  +12.77%  (p=0.008 n=5+5)
> Trace/100-1000-32     510ns ± 0%   541ns ± 1%   +6.08%  (p=0.008 n=5+5)
> Trace/100-10000-32    514ns ± 1%   540ns ± 0%   +5.14%  (p=0.008 n=5+5)
> Trace/1000-2-32      17.2µs ± 1%   1.0µs ± 1%  -94.39%  (p=0.008 n=5+5)
> Trace/1000-10-32     3.90µs ± 1%  0.64µs ± 0%  -83.68%  (p=0.008 n=5+5)
> Trace/1000-100-32     814ns ± 1%   542ns ± 0%  -33.46%  (p=0.008 n=5+5)
> Trace/1000-1000-32    503ns ± 1%   581ns ± 0%  +15.56%  (p=0.008 n=5+5)
> Trace/1000-10000-32  1.28µs ± 2%  1.03µs ± 1%  -19.68%  (p=0.008 n=5+5)
> 
> Change-Id: If7c68bb1809fb92fa5d06cb6640be5e09e1f131f
> Reviewed-on: https://go-review.googlesource.com/30374
> Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
> TryBot-Result: Gobot Gobot <gobot@golang.org>
> Reviewed-by: Ian Lance Taylor <iant@golang.org>
> 

Change-Id: I7cf25464ae836489e0af4a59a4d534a5d25ee352
Reviewed-on: https://go-review.googlesource.com/30650
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
2016-10-07 04:33:39 +00:00
Radu Berinde
88c1a61b3d trace: don't allocate all events upfront
SetMaxEvent allocates storage for all events, which is very expensive
if we want to set a high value; even with small values, the
unnecessary allocation of the initial slice is measurable.

We improve the performance by having a few events preallocated as part
of the trace, and appending as necessary. We also co-locate the flags
in event which makes it smaller (by a word).

We also add a set of benchmarks; before and after amortized cost
per-event is shown:

name                 old time/op  new time/op  delta
Trace/0-2-32         1.19µs ± 1%  0.96µs ± 0%  -18.94%  (p=0.008 n=5+5)
Trace/0-10-32         579ns ± 0%   635ns ± 1%   +9.82%  (p=0.008 n=5+5)
Trace/0-100-32        463ns ± 1%   466ns ± 1%     ~     (p=0.190 n=5+5)
Trace/0-1000-32       451ns ± 1%   451ns ± 0%     ~     (p=0.984 n=5+5)
Trace/0-10000-32      451ns ± 2%   449ns ± 1%     ~     (p=0.492 n=5+5)
Trace/10-2-32        1.41µs ± 1%  0.96µs ± 1%  -31.74%  (p=0.008 n=5+5)
Trace/10-10-32        623ns ± 1%   634ns ± 1%   +1.73%  (p=0.008 n=5+5)
Trace/10-100-32       469ns ± 1%   466ns ± 1%     ~     (p=0.357 n=5+5)
Trace/10-1000-32      452ns ± 1%   453ns ± 2%     ~     (p=0.913 n=5+5)
Trace/10-10000-32     451ns ± 1%   449ns ± 1%     ~     (p=0.175 n=5+5)
Trace/100-2-32       2.78µs ± 2%  0.97µs ± 1%  -65.28%  (p=0.008 n=5+5)
Trace/100-10-32       912ns ± 1%   637ns ± 1%  -30.23%  (p=0.008 n=5+5)
Trace/100-100-32      479ns ± 1%   541ns ± 0%  +12.77%  (p=0.008 n=5+5)
Trace/100-1000-32     510ns ± 0%   541ns ± 1%   +6.08%  (p=0.008 n=5+5)
Trace/100-10000-32    514ns ± 1%   540ns ± 0%   +5.14%  (p=0.008 n=5+5)
Trace/1000-2-32      17.2µs ± 1%   1.0µs ± 1%  -94.39%  (p=0.008 n=5+5)
Trace/1000-10-32     3.90µs ± 1%  0.64µs ± 0%  -83.68%  (p=0.008 n=5+5)
Trace/1000-100-32     814ns ± 1%   542ns ± 0%  -33.46%  (p=0.008 n=5+5)
Trace/1000-1000-32    503ns ± 1%   581ns ± 0%  +15.56%  (p=0.008 n=5+5)
Trace/1000-10000-32  1.28µs ± 2%  1.03µs ± 1%  -19.68%  (p=0.008 n=5+5)

Change-Id: If7c68bb1809fb92fa5d06cb6640be5e09e1f131f
Reviewed-on: https://go-review.googlesource.com/30374
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
2016-10-06 21:53:57 +00:00
Dave Day
35b06af072 trace: make AuthRequest robust to multiple RemoteAddr formats
Change-Id: Ia61f61d0b9395f383ff622f2d606dcd499f57776
Reviewed-on: https://go-review.googlesource.com/20588
Reviewed-by: David Symonds <dsymonds@golang.org>
2016-03-15 04:27:35 +00:00
Sameer Ajmani
4a71d18255 net/trace: add event logs.
An event log is typically associated with a long-lived object, like an
RPC connection.  Printf calls record events; Errorf calls record
events marked as errors.  The HTTP endpoint /debug/events organizes
event logs by family (usually the Go type name) and by
time-since-last-error.  The expanded view shows recent events in the
log and the call stack where the event log was created.

Change-Id: I3461e0d63f39ce6495e16300299048e572b3aa19
Reviewed-on: https://go-review.googlesource.com/12025
Reviewed-by: David Symonds <dsymonds@golang.org>
2015-08-10 02:23:08 +00:00
David Symonds
e562cdb856 trace: New package.
Package trace implements tracing of requests.
It exports an HTTP interface on /debug/requests,
and higher level packages (e.g. an RPC system)
can construct and annotate traces.

Change-Id: I67e981ed28bc6a15e4ad5a02217500505896ce1c
Reviewed-on: https://go-review.googlesource.com/10741
Reviewed-by: Nigel Tao <nigeltao@golang.org>
2015-06-05 01:29:25 +00:00