common/org.eclipse.tracecompass.common.core/src/org/eclipse/tracecompass/common/core/log/TraceCompassLogUtils.java

   1 /*******************************************************************************
   2  * Copyright (c) 2016 Ericsson
   3  *
   4  * All rights reserved. This program and the accompanying materials are
   5  * made available under the terms of the Eclipse Public License v1.0 which
   6  * accompanies this distribution, and is available at
   7  * http://www.eclipse.org/legal/epl-v10.html
   8  *******************************************************************************/
   9
  10 package org.eclipse.tracecompass.common.core.log;
  11
  12 import java.util.Arrays;
  13 import java.util.HashMap;
  14 import java.util.HashSet;
  15 import java.util.Iterator;
  16 import java.util.Map;
  17 import java.util.Map.Entry;
  18 import java.util.Set;
  19 import java.util.concurrent.atomic.AtomicInteger;
  20 import java.util.logging.Level;
  21 import java.util.logging.Logger;
  22
  23 import org.eclipse.jdt.annotation.Nullable;
  24
  25 /**
  26  * Logger helper
  27  *
  28  * This is a logger helper, it will allow entry-exit analysis to be much easier.
  29  *
  30  * The events are saved in a JSON-like message in the phase of the event. It is
  31  * an event type but with extra information associated to it. Typical types can
  32  * be the following.
  33  * <ul>
  34  * <li>Durations
  35  * <ul>
  36  * <li><strong>B</strong>, Begin</li>
  37  * <li><strong>E</strong>, End</li>
  38  * <li><strong>X</strong>, Complete, this is an event with a duration field</li>
  39  * <li><strong>i</strong>, Instant / Info</li>
  40  * </ul>
  41  * </li>
  42  * <li>Asynchronous nested messages
  43  * <ul>
  44  * <li><strong>b</strong>, nested begin</li>
  45  * <li><strong>n</strong>, nested info</li>
  46  * <li><strong>e</strong>, nested end</li>
  47  * </ul>
  48  * </li>
  49  * <li>Flows
  50  * <ul>
  51  * <li><strong>s</strong>, flow begin</li>
  52  * <li><strong>t</strong>, flow step (info)</li>
  53  * <li><strong>f</strong>, flow end</li>
  54  * </ul>
  55  * </li>
  56  * <li>Object tracking
  57  * <ul>
  58  * <li><strong>N</Strong>, Object created</li>
  59  * <li><strong>D</Strong>, Object destroyed</li>
  60  * </ul>
  61  * </li>
  62  * <li>Mark Events - events that generate markers
  63  * <ul>
  64  * <li><strong>R</strong>, Marker event</li>
  65  * </ul>
  66  * </li>
  67  * <li>CounterEvents - events that count items
  68  * <ul>
  69  * <li><strong>C</strong>, Counter event</li>
  70  * </ul>
  71  * </li>
  72  * </ul>
  73  * <p>
  74  * To use <strong>durations</strong> and/or <strong>flows</strong>, see
  75  * {@link ScopeLog} and {@link FlowScopeLog}. These 2 concepts are related.
  76  * Durations would typically be used to instrument simple methods, while flows
  77  * would be preferred if there are links to be made with other threads.
  78  * <p>
  79  * To use <strong>Asynchronous nested messages</strong>, see
  80  * {@link #traceAsyncStart(Logger, Level, String, String, int, Object...)}, and
  81  * {@link #traceAsyncEnd(Logger, Level, String, String, int, Object...)}
  82  * <p>
  83  * To use <strong>Object tracking</strong>, see
  84  * {@link #traceObjectCreation(Logger, Level, Object)} and
  85  * {@link #traceObjectDestruction(Logger, Level, Object)}
  86  *
  87  * The design philosophy of this class is very heavily inspired by the trace
  88  * event format of Google. The full specification is available <a
  89  * href=https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit?pli=1#>here</a>.
  90  * <p>
  91  *
  92  * The main goals are clarity of output and simplicity for the developer.
  93  * Performance is a nice to have, but is not the main concern of this helper. A
  94  * minor performance impact compared to simply logging the events is to be
  95  * expected.
  96  *
  97  * @author Matthew Khouzam
  98  * @since 2.3
  99  * @noinstantiate This class is not intended to be instantiated by clients. It
 100  *                is a helper class.
 101  */
 102 public final class TraceCompassLogUtils {
 103
 104     /*
 105      * Field names
 106      */
 107     private static final String ARGS = "args"; //$NON-NLS-1$
 108     private static final String NAME = "name"; //$NON-NLS-1$
 109     private static final String CATEGORY = "cat"; //$NON-NLS-1$
 110     private static final String ID = "id"; //$NON-NLS-1$
 111     private static final String TID = "tid"; //$NON-NLS-1$
 112     private static final String TIMESTAMP = "ts"; //$NON-NLS-1$
 113     private static final String PHASE = "ph"; //$NON-NLS-1$
 114
 115     private static final String ARGS_ERROR_MESSAGE = "Data should be in the form of key, value, key1, value1, ... TraceCompassScopeLog was supplied "; //$NON-NLS-1$
 116     private static final AtomicInteger ID_GENERATOR = new AtomicInteger(0);
 117
 118     private TraceCompassLogUtils() {
 119         // do nothing
 120     }
 121
 122     /**
 123      * Scope Logger helper. This will automatically log entry and exit of the
 124      * scope. This scope log will be shown under any scope enclosing it, but
 125      * will not be the source, or destination of any link to other scopes. If
 126      * relations should be done with other scopes, the {@link FlowScopeLog}
 127      * class is more appropriate.
 128      *
 129      * Usage:
 130      *
 131      * <pre>
 132      * {@code usage of ScopeLog}
 133      *  try (ScopeLog linksLogger = new ScopeLog(LOGGER, Level.CONFIG, "Perform Query")) { //$NON-NLS-1$
 134      *      ss.updateAllReferences();
 135      *      dataStore.addAll(ss.query(ts, trace));
 136      *  }
 137      * </pre>
 138      * <p>
 139      * will generate the following trace
 140      *
 141      * <pre>
 142      * {@code trace output}
 143      *  INFO: {"ts":12345,"ph":"B",tid:1,"name:Perform Query"}
 144      *  INFO: {"ts":"12366,"ph":"E","tid":1}
 145      * </pre>
 146      */
 147     public static class ScopeLog implements AutoCloseable {
 148
 149         private final long fThreadId;
 150         private final Logger fLogger;
 151         private final Level fLevel;
 152         private final Map<String, Object> fData = new HashMap<>();
 153
 154         /**
 155          * Scope logger constructor
 156          *
 157          * @param log
 158          *            the JUL logger to log to
 159          * @param level
 160          *            the log level see {@link Level}
 161          * @param label
 162          *            The label of the event pair
 163          * @param args
 164          *            Additional messages to pass for this scope, should be in
 165          *            pairs key, value, key2, value2.... typically arguments.
 166          *            Note that these arguments will be logged only at the
 167          *            beginning of the scope
 168          */
 169         public ScopeLog(Logger log, Level level, String label, Object... args) {
 170             long time = System.nanoTime();
 171             fLogger = log;
 172             fLevel = level;
 173             fThreadId = Thread.currentThread().getId();
 174             fLogger.log(fLevel, (() -> {
 175                 StringBuilder sb = new StringBuilder();
 176                 sb.append('{');
 177                 appendCommon(sb, 'B', time, fThreadId);
 178                 appendName(sb, label);
 179                 appendArgs(sb, args);
 180                 sb.append('}');
 181                 return sb.toString();
 182             }));
 183         }
 184
 185         /**
 186          * Add a tag to the scope logger, will be written at the exit. This can
 187          * save space on the trace by having a field appended to an event rather
 188          * than writing a whole new event for a small chunk of data.
 189          *
 190          * If the timing information is important than it would be more
 191          * appropriate to call
 192          * {@link TraceCompassLogUtils#traceInstant(Logger, Level, String, Object...)}
 193          *
 194          * @param name
 195          *            the name of the field
 196          * @param value
 197          *            The value of the field.
 198          */
 199         public void addData(String name, Object value) {
 200             fData.put(name, value);
 201         }
 202
 203         @Override
 204         public void close() {
 205             long time = System.nanoTime();
 206             fLogger.log(fLevel, (() -> {
 207                 StringBuilder sb = new StringBuilder();
 208                 sb.append('{');
 209                 appendCommon(sb, 'E', time, fThreadId);
 210                 return appendArgs(sb, fData).append('}').toString();
 211             }));
 212         }
 213     }
 214
 215     /**
 216      * Builder class for the {@link FlowScopeLog}. One can either set a category
 217      * or a parent scope before building the flow scope log. If none is set, a
 218      * default category called "null" will be used.
 219      *
 220      * @author Geneviève Bastien
 221      */
 222     public static class FlowScopeLogBuilder {
 223
 224         private final Logger fLogger;
 225         private final Level fLevel;
 226         private final String fLabel;
 227         private final Object[] fArgs;
 228         private @Nullable String fCategory = null;
 229         private @Nullable FlowScopeLog fParent = null;
 230
 231         /**
 232          * Flow scope log builder constructor
 233          *
 234          * @param logger
 235          *            the JUL logger
 236          * @param level
 237          *            the log level see {@link Level}
 238          * @param label
 239          *            The label of the event pair
 240          * @param args
 241          *            the messages to pass, should be in pairs key, value, key2,
 242          *            value2.... typically arguments
 243          */
 244         public FlowScopeLogBuilder(Logger logger, Level level, String label, Object... args) {
 245             fLogger = logger;
 246             fLevel = level;
 247             fLabel = label;
 248             fArgs = args;
 249         }
 250
 251         /**
 252          * Set a category for the flow scope. When building the scope, an ID
 253          * will be automatically generated.
 254          *
 255          * This method is mutually exclusive with
 256          * {@link #setParentScope(FlowScopeLog)}. Calling both will throw an
 257          * exception.
 258          *
 259          * @param category
 260          *            The category of this flow
 261          * @return This builder
 262          */
 263         public FlowScopeLogBuilder setCategory(String category) {
 264             if (fParent != null) {
 265                 throw new IllegalStateException("FlowScopeLogBuilder: Cannot set a category if a parent has already been set"); //$NON-NLS-1$
 266             }
 267             fCategory = category;
 268             return this;
 269         }
 270
 271         /**
 272          * Set a parent scope for the flow scope to build. The scope will have
 273          * the same category and ID as the parent scope.
 274          *
 275          * This method is mutually exclusive with {@link #setCategory(String)}.
 276          * Calling both will throw an exception.
 277          *
 278          * @param parent
 279          *            The parent scope
 280          * @return This builder
 281          */
 282         public FlowScopeLogBuilder setParentScope(FlowScopeLog parent) {
 283             if (fCategory != null) {
 284                 throw new IllegalStateException("FlowScopeLogBuilder: Cannot set a parent scope if a category has already been set"); //$NON-NLS-1$
 285             }
 286             fParent = parent;
 287             return this;
 288         }
 289
 290         /**
 291          * Build the flow scope log
 292          *
 293          * @return The flow scope log
 294          */
 295         public FlowScopeLog build() {
 296             FlowScopeLog parent = fParent;
 297             if (parent != null) {
 298                 return new FlowScopeLog(fLogger, fLevel, fLabel, parent.fCategory, parent.fId, fArgs);
 299             }
 300             return new FlowScopeLog(fLogger, fLevel, fLabel, String.valueOf(fCategory), ID_GENERATOR.incrementAndGet(), fArgs);
 301         }
 302
 303     }
 304
 305     /**
 306      * Flow Scope Logger helper. It will automatically log entry and exit of the
 307      * scope. It can be used with other flow scopes to follow the program flow
 308      * across threads. To do so, these scopes save more data, so take more disk
 309      * space. If there is no inter-process/thread communication to follow, the
 310      * {@link ScopeLog} class would be more appropriate.
 311      *
 312      * Usage: this can be used to track asynchronous threads communication. This
 313      * can be used in scatter-gather/map-reduce operations as well as threads
 314      * that trigger a UI Thread operation.
 315      *
 316      * <pre>
 317      * {@code usage of FlowScopeLog}
 318      *  try (FlowScopeLog linksLogger = new FlowScopeLog(LOGGER, Level.CONFIG, "Perform Query", "category", 0x100)) { //$NON-NLS-1$
 319      *      Display.asynchExec(()->{
 320      *      try(FlowScopeLog linksLogger2 = new FlowScopeLog(LOGGER, Level.CONFIG, "Update UI", "category", linksLogger.getId()) {
 321      *          linksLogger.step("updating ui");
 322      *      };
 323      *      linksLogger.step("forked thread");
 324      *  }
 325      * </pre>
 326      * <p>
 327      * will generate the following trace (order not guaranteed)
 328      *
 329      * <pre>
 330      * {@code trace output}
 331      *  INFO: {"ts":12345,"ph":"s",tid:1,"name":"Perform Query", "cat":"category", "id":256}
 332      *  INFO: {"ts":12346","ph":"t",tid:1,"name":"forked thread","cat":"category", "id":256}
 333      *  INFO: {"ts":"12366,"ph":"f","tid":1,"cat":"category", "id":256}
 334      *  INFO: {"ts":12400,"ph":"s",tid:0,"name":"Update UI","cat":"category", "id":256}
 335      *  INFO: {"ts":12416","ph":"t",tid:0,"name":"updating ui", "cat":"category", "id":256}
 336      *  INFO: {"ts":"12420,"ph":"f","tid":0,"cat":"category", "id":256}
 337      * </pre>
 338      */
 339     public static class FlowScopeLog implements AutoCloseable {
 340
 341         private final long fThreadId;
 342         private final Logger fLogger;
 343         private final Level fLevel;
 344         private final int fId;
 345         private final String fCategory;
 346         private final Map<String, Object> fData = new HashMap<>();
 347
 348         /**
 349          * Flow scope logger constructor
 350          *
 351          * @param log
 352          *            the JUL logger
 353          * @param level
 354          *            the log level see {@link Level}
 355          * @param label
 356          *            The label of the event pair
 357          * @param category
 358          *            the category of the flow events
 359          * @param id
 360          *            The id of the flow
 361          * @param args
 362          *            the messages to pass, should be in pairs key, value, key2,
 363          *            value2.... typically arguments
 364          */
 365         private FlowScopeLog(Logger log, Level level, String label, String category, int id, Object... args) {
 366             long time = System.nanoTime();
 367             fId = id;
 368             fLogger = log;
 369             fLevel = level;
 370             fCategory = category;
 371             fThreadId = Thread.currentThread().getId();
 372             fLogger.log(fLevel, (() -> {
 373                 StringBuilder sb = new StringBuilder();
 374                 sb.append('{');
 375                 appendCommon(sb, 's', time, fThreadId);
 376                 appendName(sb, label);
 377                 appendCategory(sb, category);
 378                 appendId(sb, fId);
 379                 appendArgs(sb, args);
 380                 sb.append('}');
 381                 return sb.toString();
 382             }));
 383         }
 384
 385         /**
 386          * Flow step, could be launching a new process or simply hit a
 387          * checkpoint
 388          *
 389          * @param label
 390          *            The label for this step
 391          * @param args
 392          *            the arguments to log
 393          */
 394         public void step(String label, Object... args) {
 395             long time = System.nanoTime();
 396             fLogger.log(fLevel, (() -> {
 397                 StringBuilder sb = new StringBuilder();
 398                 sb.append('{');
 399                 appendCommon(sb, 't', time, fThreadId);
 400                 appendName(sb, label);
 401                 appendCategory(sb, fCategory);
 402                 appendId(sb, fId);
 403                 appendArgs(sb, args);
 404                 sb.append('}');
 405                 return sb.toString();
 406             }));
 407         }
 408
 409         /**
 410          * Add a tag to the scope logger, will be written at the exit. This can
 411          * save space on the trace by having a field appended to an event rather
 412          * than writing a whole new event for a small chunk of data.
 413          *
 414          *
 415          * If the timing information is important, then it would be more
 416          * appropriate to call {@link #step(String, Object...)}
 417          *
 418          * @param name
 419          *            the name of the field
 420          * @param value
 421          *            The value of the field.
 422          */
 423         public void addData(String name, Object value) {
 424             fData.put(name, value);
 425         }
 426
 427         @Override
 428         public void close() {
 429             long time = System.nanoTime();
 430             fLogger.log(fLevel, (() -> {
 431                 StringBuilder sb = new StringBuilder();
 432                 sb.append('{');
 433                 appendCommon(sb, 'f', time, fThreadId);
 434                 appendCategory(sb, fCategory);
 435                 appendId(sb, fId);
 436                 appendArgs(sb, fData);
 437                 sb.append('}');
 438                 return sb.toString();
 439             }));
 440         }
 441     }
 442
 443     /**
 444      * Trace Object Creation, logs the beginning of an object's life cycle.
 445      * Typically one can put this in the object's constructor. However if an
 446      * object is mutable, it can be tracked through phases with this method,
 447      * then the object can be re-used, however, the resulting analyses may yield
 448      * erroneous data if precautions are not taken.
 449      *
 450      * For mutable objects, save the return value of the call. This will be
 451      * passed to the destruction of the object and then it can be matched.
 452      *
 453      * @param logger
 454      *            The JUL logger
 455      * @param level
 456      *            The {@link Level} of this event.
 457      * @param item
 458      *            the Object to trace
 459      * @return The unique ID of this object (there may be collisions)
 460      */
 461     public static int traceObjectCreation(Logger logger, Level level, Object item) {
 462         long time = System.nanoTime();
 463         long threadId = Thread.currentThread().getId();
 464         int identityHashCode = System.identityHashCode(item);
 465         logger.log(level, () -> {
 466             StringBuilder sb = new StringBuilder();
 467             sb.append('{');
 468             appendCommon(sb, 'N', time, threadId);
 469             appendName(sb, item.getClass().getSimpleName());
 470             appendId(sb, identityHashCode);
 471             return sb.append('}').toString();
 472         });
 473         return identityHashCode;
 474     }
 475
 476     /**
 477      * Trace Object Destruction, logs the end of an object's life cycle.
 478      * Typically one can put this in the object's Dispose(). However if an
 479      * object is mutable, it can be tracked through phases with this method,
 480      * then the object can be re-used, however, the resulting analyses may yield
 481      * erroneous data if precautions are not taken.
 482      *
 483      * @param logger
 484      *            The JUL logger
 485      * @param level
 486      *            The {@link Level} of this event.
 487      * @param item
 488      *            the Object to trace
 489      */
 490     public static void traceObjectDestruction(Logger logger, Level level, Object item) {
 491         long time = System.nanoTime();
 492         long threadId = Thread.currentThread().getId();
 493         logger.log(level, () -> {
 494             StringBuilder sb = new StringBuilder();
 495             sb.append('{');
 496             appendCommon(sb, 'D', time, threadId);
 497             appendName(sb, item.getClass().getSimpleName());
 498             appendId(sb, System.identityHashCode(item));
 499             return sb.append('}').toString();
 500         });
 501     }
 502
 503     /**
 504      * Trace Object Destruction, logs the end of an object's life cycle.
 505      * Typically one can put this in the object's Dispose(). However if an
 506      * object is mutable, it can be tracked through phases with this method,
 507      * then the object can be re-used, however, the resulting analyses may be
 508      *
 509      * @param logger
 510      *            The JUL logger
 511      * @param level
 512      *            The {@link Level} of this event.
 513      * @param item
 514      *            the Object to trace
 515      * @param uniqueId
 516      *            The unique ID
 517      */
 518     public static void traceObjectDestruction(Logger logger, Level level, Object item, int uniqueId) {
 519         long time = System.nanoTime();
 520         long threadId = Thread.currentThread().getId();
 521         logger.log(level, () -> {
 522             StringBuilder sb = new StringBuilder();
 523             sb.append('{');
 524             appendCommon(sb, 'D', time, threadId);
 525             appendName(sb, item.getClass().getSimpleName());
 526             appendId(sb, uniqueId);
 527             return sb.append('}').toString();
 528         });
 529     }
 530
 531     /**
 532      * Asynchronous events are used to specify asynchronous operations, such as
 533      * an asynchronous (or synchronous) draw, or a network operation. Call this
 534      * method at the beginning of such an operation.
 535      *
 536      * @param logger
 537      *            The JUL logger
 538      * @param level
 539      *            The {@link Level} of this event.
 540      * @param name
 541      *            The name of the asynchronous message
 542      * @param category
 543      *            the category of the asynchronous event
 544      * @param id
 545      *            The unique ID of a transaction
 546      * @param args
 547      *            Additional arguments to log
 548      */
 549     public static void traceAsyncStart(Logger logger, Level level, @Nullable String name, @Nullable String category, int id, Object... args) {
 550         long time = System.nanoTime();
 551         long threadId = Thread.currentThread().getId();
 552         logger.log(level, () -> {
 553             StringBuilder sb = new StringBuilder();
 554             sb.append('{');
 555             appendCommon(sb, 'b', time, threadId);
 556             appendName(sb, name);
 557             appendCategory(sb, category);
 558             appendId(sb, id);
 559             return appendArgs(sb, args).append('}').toString();
 560         });
 561     }
 562
 563     /**
 564      * Asynchronous events are used to specify asynchronous operations, such as
 565      * an asynchronous (or synchronous) draw, or a network operation. Call this
 566      * method to augment the asynchronous event with nested information.
 567      *
 568      * @param logger
 569      *            The JUL logger
 570      * @param level
 571      *            The {@link Level} of this event.
 572      * @param name
 573      *            The name of the asynchronous message
 574      * @param category
 575      *            the category of the asynchronous event
 576      * @param id
 577      *            The unique ID of a transaction
 578      * @param args
 579      *            Additional arguments to log
 580      */
 581     public static void traceAsyncNested(Logger logger, Level level, @Nullable String name, @Nullable String category, int id, Object... args) {
 582         long time = System.nanoTime();
 583         long threadId = Thread.currentThread().getId();
 584         logger.log(level, () -> {
 585             StringBuilder sb = new StringBuilder();
 586             sb.append('{');
 587             appendCommon(sb, 'n', time, threadId);
 588             appendName(sb, name);
 589             appendCategory(sb, category);
 590             appendId(sb, id);
 591             return appendArgs(sb, args).append('}').toString();
 592         });
 593     }
 594
 595     /**
 596      * Asynchronous events are used to specify asynchronous operations, such as
 597      * an asynchronous (or synchronous) draw, or a network operation. Call this
 598      * method at the end of such an operation.
 599      *
 600      * @param logger
 601      *            The JUL logger
 602      * @param level
 603      *            The {@link Level} of this event.
 604      * @param name
 605      *            The name of the asynchronous message
 606      * @param category
 607      *            the category of the asynchronous event
 608      * @param id
 609      *            The unique ID of a transaction
 610      * @param args
 611      *            Additional arguments to log
 612      */
 613     public static void traceAsyncEnd(Logger logger, Level level, @Nullable String name, @Nullable String category, int id, Object... args) {
 614         long time = System.nanoTime();
 615         long threadId = Thread.currentThread().getId();
 616         logger.log(level, () -> {
 617             StringBuilder sb = new StringBuilder();
 618             sb.append('{');
 619             appendCommon(sb, 'e', time, threadId);
 620             appendName(sb, name);
 621             appendCategory(sb, category);
 622             appendId(sb, id);
 623             return appendArgs(sb, args).append('}').toString();
 624         });
 625     }
 626
 627     /**
 628      * Instant events, created to indicate an item of interest has occurred,
 629      * similar to a standard System.out.println() or a
 630      * Java.util.Logger#log(Level). This one provides an event in a more
 631      * structured way. This should be the method to call to save data that
 632      * should have a zero duration, as it will ensure a log format that can then
 633      * be parsed by a trace type.
 634      *
 635      * @param logger
 636      *            The JUL logger
 637      * @param level
 638      *            The {@link Level} of this event.
 639      * @param name
 640      *            The name of the asynchronous message
 641      * @param args
 642      *            Additional arguments to log
 643      */
 644     public static void traceInstant(Logger logger, Level level, String name, Object... args) {
 645         long time = System.nanoTime();
 646         long threadId = Thread.currentThread().getId();
 647         logger.log(level, () -> {
 648             StringBuilder sb = new StringBuilder();
 649             sb.append('{');
 650             appendCommon(sb, 'i', time, threadId);
 651             appendName(sb, name);
 652             return appendArgs(sb, args).append('}').toString();
 653         });
 654     }
 655
 656     /**
 657      * The counter events can track a value or multiple values as they change
 658      * over time.
 659      *
 660      * @param logger
 661      *            The Logger
 662      * @param level
 663      *            The {@link Level} of this event.
 664      * @param name
 665      *            The name of the asynchronous message
 666      * @param args
 667      *            The counters to log in the format : "title", value
 668      */
 669     public static void traceCounter(Logger logger, Level level, @Nullable String name, Object... args) {
 670         long time = System.nanoTime();
 671         long threadId = Thread.currentThread().getId();
 672         logger.log(level, () -> {
 673             StringBuilder sb = new StringBuilder();
 674             sb.append('{');
 675             appendCommon(sb, 'C', time, threadId);
 676             appendName(sb, name);
 677             return appendArgs(sb, args).append('}').toString();
 678         });
 679     }
 680
 681     // -------------------------------------------------------------------------
 682     // Helpers
 683     // -------------------------------------------------------------------------
 684
 685     /*
 686      * USE ME FIRST
 687      */
 688     private static StringBuilder appendCommon(StringBuilder appendTo, char phase, long time, long threadId) {
 689         writeObject(appendTo, TIMESTAMP, time).append(','); // $NON-NLS-1$
 690         writeObject(appendTo, PHASE, phase).append(',');
 691         return writeObject(appendTo, TID, threadId); // $NON-NLS-1$
 692     }
 693
 694     private static StringBuilder appendName(StringBuilder sb, @Nullable String name) {
 695         if (name != null) {
 696             sb.append(',');
 697             writeObject(sb, NAME, name);
 698         }
 699         return sb;
 700     }
 701
 702     private static StringBuilder appendCategory(StringBuilder sb, @Nullable String category) {
 703         if (category != null) {
 704             sb.append(',');
 705             writeObject(sb, CATEGORY, category);
 706         }
 707         return sb;
 708     }
 709
 710     private static StringBuilder appendId(StringBuilder sb, int id) {
 711         return sb.append(',')
 712                 .append('"')
 713                 .append(ID)
 714                 .append("\":\"0x") //$NON-NLS-1$
 715                 .append(Integer.toHexString(id))
 716                 .append('"');
 717     }
 718
 719     private static StringBuilder appendArgs(StringBuilder sb, Map<String, Object> args) {
 720         if (!args.isEmpty()) {
 721             sb.append(',')
 722                     .append('"')
 723                     .append(ARGS)
 724                     .append('"')
 725                     .append(':');
 726             Object[] argsArray = new Object[2 * args.size()];
 727             Iterator<Entry<String, Object>> entryIter = args.entrySet().iterator();
 728             for (int i = 0; i < args.size(); i++) {
 729                 Entry<String, Object> entry = entryIter.next();
 730                 argsArray[i] = entry.getKey();
 731                 argsArray[i + 1] = entry.getValue();
 732             }
 733             getArgs(sb, argsArray);
 734         }
 735         return sb;
 736     }
 737
 738     private static StringBuilder appendArgs(StringBuilder sb, Object... args) {
 739         if (args.length > 0) {
 740             sb.append(',')
 741                     .append('"')
 742                     .append(ARGS)
 743                     .append('"')
 744                     .append(':');
 745             getArgs(sb, args);
 746         }
 747         return sb;
 748     }
 749
 750     private static StringBuilder getArgs(StringBuilder appendTo, Object[] data) {
 751         if (data.length == 0) {
 752             return appendTo;
 753         }
 754         Set<String> tester = new HashSet<>();
 755         appendTo.append('{');
 756         if (data.length == 1) {
 757             // not in contract, but let's assume here that people are still new
 758             // at this
 759             appendTo.append("\"msg\":\"").append(data[0]).append('"'); //$NON-NLS-1$
 760         } else {
 761             if (data.length % 2 != 0) {
 762                 throw new IllegalArgumentException(
 763                         ARGS_ERROR_MESSAGE + "an odd number of messages" + Arrays.asList(data).toString()); //$NON-NLS-1$
 764             }
 765             for (int i = 0; i < data.length - 1; i += 2) {
 766                 Object value = data[i + 1];
 767                 String keyVal = String.valueOf(data[i]);
 768                 if (tester.contains(keyVal)) {
 769                     throw new IllegalArgumentException(ARGS_ERROR_MESSAGE + "an duplicate field names : " + keyVal); //$NON-NLS-1$
 770                 }
 771                 tester.add(keyVal);
 772                 if (i > 0) {
 773                     appendTo.append(',');
 774                 }
 775                 writeObject(appendTo, keyVal, value);
 776             }
 777         }
 778
 779         return appendTo.append('}');
 780     }
 781
 782     private static StringBuilder writeObject(StringBuilder appendTo, Object key, @Nullable Object value) {
 783         appendTo.append('"').append(key).append('"').append(':');
 784         if (value instanceof Number) {
 785             appendTo.append(value);
 786         } else {
 787             appendTo.append('"').append(String.valueOf(value)).append('"');
 788         }
 789         return appendTo;
 790     }
 791
 792 }