Optimize log hot path

[jack-berg]

Followup to #4891.

Reduces allocations on happy path by avoiding creation of extra InstrumentationScopeInfo / InstrumentationScopeInfoBuilder instances that aren't strictly needed. Does this by adjusting changing ComponentRegistry#get(InstrumentationScopeInfo) to ComponentRegistry#get(String name, @Nullable String version, @Nullable String schemaUrl, Attributes attributes), and only building InstrumentationScopeInfo the first time we see a component with a particular identity.

Benchmark before:

Benchmark                                                  Mode  Cnt     Score     Error   Units
LogsBenchmarks.emitSimpleLog                               avgt   10    35.035 ±   0.732   ns/op
LogsBenchmarks.emitSimpleLog:·gc.alloc.rate                avgt   10  2173.006 ±  43.649  MB/sec
LogsBenchmarks.emitSimpleLog:·gc.alloc.rate.norm           avgt   10   120.000 ±   0.001    B/op
LogsBenchmarks.emitSimpleLog:·gc.churn.G1_Eden_Space       avgt   10  2191.457 ± 429.679  MB/sec
LogsBenchmarks.emitSimpleLog:·gc.churn.G1_Eden_Space.norm  avgt   10   120.983 ±  23.200    B/op
LogsBenchmarks.emitSimpleLog:·gc.count                     avgt   10    37.000            counts
LogsBenchmarks.emitSimpleLog:·gc.time                      avgt   10    30.000                ms

Benchmark after:

Benchmark                                                  Mode  Cnt     Score     Error   Units
LogsBenchmarks.emitSimpleLog                               avgt   10    29.155 ±   1.023   ns/op
LogsBenchmarks.emitSimpleLog:·gc.alloc.rate                avgt   10  1220.007 ±  36.921  MB/sec
LogsBenchmarks.emitSimpleLog:·gc.alloc.rate.norm           avgt   10    56.048 ±   0.231    B/op
LogsBenchmarks.emitSimpleLog:·gc.churn.G1_Eden_Space       avgt   10  1241.334 ± 191.229  MB/sec
LogsBenchmarks.emitSimpleLog:·gc.churn.G1_Eden_Space.norm  avgt   10    57.041 ±   8.784    B/op
LogsBenchmarks.emitSimpleLog:·gc.count                     avgt   10    31.000            counts
LogsBenchmarks.emitSimpleLog:·gc.time                      avgt   10    27.000                ms

Notice the significant reduction in allocation rate.

[codecov]

Codecov Report

Base: 90.89% // Head: 90.93% // Increases project coverage by +0.03% 🎉

Coverage data is based on head (af529fc) compared to base (435411b).
Patch coverage: 100.00% of modified lines in pull request are covered.

Additional details and impacted files

@@             Coverage Diff              @@
##               main    #4913      +/-   ##
============================================
+ Coverage     90.89%   90.93%   +0.03%     
- Complexity     4804     4816      +12     
============================================
  Files           545      545              
  Lines         14340    14382      +42     
  Branches       1383     1382       -1     
============================================
+ Hits          13035    13078      +43     
  Misses          898      898              
+ Partials        407      406       -1     

Impacted Files	Coverage Δ
.../opentelemetry/sdk/internal/ComponentRegistry.java	100.00% <100.00%> (+9.09%)	⬆️
...va/io/opentelemetry/sdk/logs/SdkLoggerBuilder.java	100.00% <100.00%> (ø)
...a/io/opentelemetry/sdk/logs/SdkLoggerProvider.java	100.00% <100.00%> (ø)
.../io/opentelemetry/sdk/metrics/SdkMeterBuilder.java	100.00% <100.00%> (ø)
...a/io/opentelemetry/sdk/trace/SdkTracerBuilder.java	100.00% <100.00%> (ø)
...ava/io/opentelemetry/sdk/internal/RateLimiter.java	94.11% <0.00%> (-5.89%)	⬇️
...entelemetry/api/internal/ImmutableSpanContext.java	100.00% <0.00%> (ø)
...metry/sdk/logs/export/BatchLogRecordProcessor.java	89.70% <0.00%> (+0.73%)	⬆️

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

☔ View full report at Codecov.
📢 Do you have feedback about the report comment? Let us know in this issue.

[mateuszrzeszutek]

Awesome! 🚀

[jkwatson]

No real problem with this optimization, but is this really on the hot path? Shouldn't people be initializing their loggers/tracers/etc once, rather than fetching them every time?

[jack-berg]

Shouldn't people be initializing their loggers/tracers/etc once, rather than fetching them every time?

With tracers and meters, yes. But log appender implementations use the logger name as the name of the logger, so they have to get a logger for each log record they process. Here's an example from the log4j appender. The logback and jul implementations work the same way. The appenders could implement their own cache of loggers by maintaining a map of logger name to logger, but if that's a pattern all implementations will have to do we should probably solve it in the SDK.

[jkwatson]

Shouldn't people be initializing their loggers/tracers/etc once, rather than fetching them every time?

With tracers and meters, yes. But log appender implementations use the logger name as the name of the logger, so they have to get a logger for each log record they process. Here's an example from the log4j appender. The logback and jul implementations work the same way. The appenders could implement their own cache of loggers by maintaining a map of logger name to logger, but if that's a pattern all implementations will have to do we should probably solve it in the SDK.

ah, I see. for the appender case, that makes sense. thanks!