[GitHub] [pinot] gortiz commented on a diff in pull request #10977: allow to add custom context into query trace

["gortiz (via GitHub)" <gi...@apache.org>]

gortiz commented on code in PR #10977:
URL: https://github.com/apache/pinot/pull/10977#discussion_r1244761724


##########
pinot-core/src/main/java/org/apache/pinot/core/util/trace/BuiltInTracer.java:
##########
@@ -50,6 +50,15 @@ public void close() {
       }
       TraceContext.logTime(operatorName, duration);
     }
+
+    @Override
+    public void close(Object context) {
+      String operatorName = _operator.getSimpleName();
+      if (LOGGER.isTraceEnabled()) {

Review Comment:
   The rule is (assuming `string` and `concatenation` are actual variables decided in runtime):
   - Most expensive option: `Logger.trace("some " + string + " with " + concatenation)` calls toString on the variables and concatenates the strings (which is quite expensive in terms of allocating and moving) each time we evaluate that, even when trace is disabled
   - Second most expensive option:
      - `Logger.trace("some {} string with {}", string, concatenation)` is a syntactic sugar of `Logger.trace("some {} string with {}", new String[string, concatenation])`, which creates an array each time we evaluate the line, even if trace is disabled. This construction does not eagerly call toString on the variables and just create an array of pointers, which is around 32 bytes per variable we use. It also doesn't need to concatenate it, so it is cheaper in terms of moving memory
      - Log4J2 has also a construction like: `Logger.trace(() -> "some " + string + " with " + concatenation)`. This is similar to the previous option: It allocates a lambda instead of an array but does not call toString and may be easier to read.
   -  Cheapest option:
     - `if (LOGGER.isTraceEnabled()) { `Logger.trace("some " + string + " with " + concatenation)`;}`. Given that we only execute LOGGER.trace(...) if LOGGER.isTraceEnabled() is true, then we only evalute the string is we are going to actually print it somewhere.
   
   This applies not only to trace, but to all other logging methods. But trace is almost never actually printed, while error, warn are almost always printed and info is printed very often. Therefore we should always try to use this techniques in the hotpath, but the actual benefit is gonna be there in debug or tracer cases.
   
   BTW, it is important to note that this only matters when we concatenate actual variables. Things like:
   
   ```
   String literal = "world"
   Logger.trace("hello " + literal)
   ```
   
   or
   
   ```
   Logger.trace("this is a very long sentence " +
     "so I'm going to write it in two lines")
   ```
   
   Are fine as Java should optimize them. In the second case the optimization will be done for sure by javac, so we can even verify that with javah (which shows the bytecode of a .class). In the first case I'm not sure whether javac will optimize that, but the JIT should optimize it.
   



-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org


---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org