Java 类org.slf4j.profiler.Profiler 实例源码

/**
 * Create stock event.
 *
 * @param eventDto a stock event bound to request body.
 * @return created stock event's ID.
 */
@RequestMapping(value = "stockEvents", method = POST)
public ResponseEntity<UUID> createStockEvent(@RequestBody StockEventDto eventDto) {
  LOGGER.debug("Try to create a stock event");

  XLOGGER.entry(eventDto);
  Profiler profiler = new Profiler("CREATE_STOCK_EVENT");
  profiler.setLogger(XLOGGER);

  checkPermission(eventDto, profiler.startNested("CHECK_PERMISSION"));

  profiler.start("PROCESS");
  UUID createdEventId = stockEventProcessor.process(eventDto);

  profiler.start("CREATE_RESPONSE");
  ResponseEntity<UUID> response = new ResponseEntity<>(createdEventId, CREATED);

  profiler.stop().log();
  XLOGGER.exit(response);

  return response;
}

private void checkPermission(StockEventDto eventDto, Profiler profiler) {
  OAuth2Authentication authentication = (OAuth2Authentication) SecurityContextHolder
      .getContext().getAuthentication();

  if (!authentication.isClientOnly()) {
    UUID programId = eventDto.getProgramId();
    UUID facilityId = eventDto.getFacilityId();

    profiler.start("CHECK_PROGRAM_SUPPORTED_BY_HOME_FACILITY");
    homeFacilityPermissionService.checkProgramSupported(programId);

    if (eventDto.isPhysicalInventory()) {
      profiler.start("CAN_EDIT_PHYSICAL_INVENTORY");
      permissionService.canEditPhysicalInventory(programId, facilityId);
    } else {
      //we check STOCK_ADJUST permission for both adjustment and issue/receive
      //this may change in the future
      profiler.start("CAN_ADJUST_STOCK");
      permissionService.canAdjustStock(programId, facilityId);
    }
  }
}

/**
 * Validate and persist event and create stock card and line items from it.
 *
 * @param eventDto stock event dto.
 * @return the persisted event ids.
 */

public UUID process(StockEventDto eventDto) {
  XLOGGER.entry(eventDto);
  Profiler profiler = new Profiler("PROCESS");
  profiler.setLogger(XLOGGER);

  profiler.start("BUILD_CONTEXT");
  StockEventProcessContext context = contextBuilder.buildContext(eventDto);
  eventDto.setContext(context);

  profiler.start("VALIDATE");
  stockEventValidationsService.validate(eventDto);

  UUID eventId = saveEventAndGenerateLineItems(
      eventDto, profiler.startNested("SAVE_AND_GENERATE_LINE_ITEMS")
  );

  profiler.stop().log();
  XLOGGER.exit(eventId);

  return eventId;
}

private UUID saveEventAndGenerateLineItems(StockEventDto eventDto, Profiler profiler) {
  profiler.start("CONVERT_TO_EVENT");
  StockEvent stockEvent = eventDto.toEvent();

  profiler.start("DB_SAVE");
  UUID savedEventId = stockEventsRepository.save(stockEvent).getId();
  LOGGER.debug("Saved stock event with id " + savedEventId);

  if (eventDto.isPhysicalInventory()) {
    profiler.start("CREATE_PHYSICAL_INVENTORY_DTO");
    PhysicalInventoryDto inventoryDto = fromEventDto(eventDto);

    profiler.start("SUBMIT_PHYSICAL_INVENTORY");
    physicalInventoryService.submitPhysicalInventory(inventoryDto, savedEventId);
  }

  profiler.start("SAVE_FROM_EVENT");
  stockCardService.saveFromEvent(eventDto, savedEventId);

  profiler.start("CALL_NOTIFICATIONS");
  stockEventNotificationProcessor.callAllNotifications(eventDto);

  return savedEventId;
}

private void popActiveProfiler() {
    List<Profiler> thisThreadsProfilers = activeProfilers.getIfPresent(Thread.currentThread());
    if (thisThreadsProfilers != null) {
        Profiler cp = thisThreadsProfilers.remove(thisThreadsProfilers.size() - 1);
        cp.stop();
        MDC.put(getMDCProfileInfoKey(), "" + cp.elapsedTime());
        // If not at the root profiler, then track the root information too.
        if (thisThreadsProfilers.size() > 0) {
            MDC.put(getMDCRootProfileInfoKey(), "" + (System.nanoTime() - activeRootProfilerStart.getIfPresent(Thread.currentThread())));
        }
        // Ensure clean up fully.
        if (thisThreadsProfilers.size() == 0) {
            activeProfilers.invalidate(Thread.currentThread());
            activeRootProfilerStart.invalidate(Thread.currentThread());
        }
    }
}

@Test
@Category(IntegrationTest.class)
public void scan() {
  Project project = project().validProject();
  Profiler profiler = new Profiler("Scanner");
  profiler.setLogger(logger);
  when(metricRegistry.meter(anyString())).thenReturn(new Meter());
  CommitMetadataScanner scanner =
      new CommitMetadataScanner(commitRepository, updater, metricRegistry);
  when(projectRepository.findOne(project.getId())).thenReturn(createProject());
  profiler.start("scanning without local repository present");
  File repoRoot = scanner.scan(project).getParentFile();
  Assert.assertTrue(gitChecker.isRepository(repoRoot.toPath()));
  // scanning again should be fairly quick, since the repository is already cloned
  profiler.start("re-scanning with local repository present from last test");
  scanner.scan(project);
  Assert.assertTrue(gitChecker.isRepository(repoRoot.toPath()));

  verify(commitRepository, atLeast(20)).save(any(Commit.class));
  profiler.stop().log();
}

/**
 * Starts the container using docker, pulling an image if necessary.
 */
public void start() {
    Profiler profiler = new Profiler("Container startup");
    profiler.setLogger(logger());

    try {
        profiler.start("Prepare container configuration and host configuration");
        configure();

        logger().debug("Starting container: {}", getDockerImageName());
        logger().debug("Trying to start container: {}", image.get());

        AtomicInteger attempt = new AtomicInteger(0);
        Unreliables.retryUntilSuccess(startupAttempts, () -> {
            logger().debug("Trying to start container: {} (attempt {}/{})", image.get(), attempt.incrementAndGet(), startupAttempts);
            tryStart(profiler.startNested("Container startup attempt"));
            return true;
        });

    } catch (Exception e) {
        throw new ContainerLaunchException("Container startup failed", e);
    } finally {
        profiler.stop().log();
    }
}

@Override
@VisibleForTesting
public void starting(Description description) {
    final Profiler profiler = new Profiler("Docker Compose container rule");
    profiler.setLogger(logger());
    profiler.start("Docker Compose container startup");

    synchronized (MUTEX) {
        if (pull) {
            pullImages();
        }
        applyScaling(); // scale before up, so that all scaled instances are available first for linking
        createServices();
        if (tailChildContainers) {
            tailChildContainerLogs();
        }
        registerContainersForShutdown();
        startAmbassadorContainers(profiler);
    }
}

@Override
public synchronized Query createQuery ( final QueryParameters parameters, final QueryListener listener, final boolean updateData )
{
    final Profiler p = new Profiler ( "hi.createQuery" );
    p.setLogger ( logger );

    if ( this.service == null )
    {
        logger.warn ( "We have no service. We cannot create a query" );
        return null;
    }

    p.start ( "call shi.createQuery" );

    final WrapperQuery query = new WrapperQuery ( this.service.createQuery ( parameters, listener, updateData ) );
    if ( query.isValid () )
    {
        this.openQueries.add ( query );
    }
    else
    {
        logger.warn ( "We have an invalid query" );
    }

    p.stop ().log ();

    return query;
}

protected synchronized void handleCloseQuery ( final CloseQuery message )
{
    final Profiler p = new Profiler ( "Close Query" );
    p.setLogger ( logger );

    p.start ( "init" );

    // get the query id
    final long queryId = message.getQueryId ();

    logger.info ( "Handle close query: {}", queryId );

    final QueryHandler handler;

    p.start ( "remove" );

    sendQueryState ( queryId, QueryState.DISCONNECTED );
    handler = this.queries.remove ( queryId );

    // close outside of lock
    if ( handler != null )
    {
        p.start ( "Close" );
        // throw it in the disposer queue ... the storage module takes too long
        this.queryDisposer.execute ( new Runnable () {

            @Override
            public void run ()
            {
                logger.info ( "Disposing query {} ...", queryId );
                handler.close ();
                logger.info ( "Disposing query {} ... done!", queryId );
            }
        } );
    }

    p.stop ().log ();
}

protected void handleCreateQuery ( final CreateQuery message )
{
    final Profiler p = new Profiler ( "Create query" );
    p.setLogger ( logger );

    // get the query id
    final long queryId = message.getQueryId ();

    logger.debug ( "Creating new query with id: {}", queryId );

    try
    {
        p.start ( "Prepare" );

        // get the query item
        final String itemId = message.getItemId ();
        // get the initial query parameters
        final QueryParameters parameters = message.getQueryParameters ();
        final boolean updateData = message.isUpdateData ();

        p.start ( "Make query" );
        makeQuery ( message, queryId, itemId, parameters, updateData );

        p.start ( "Finish" );
    }
    catch ( final Throwable e )
    {
        sendQueryState ( queryId, QueryState.DISCONNECTED );
    }
    finally
    {
        p.stop ().log ();
    }
}

private void callNotifications(StockEventDto event, StockEventLineItemDto eventLine) {
  XLOGGER.entry(event, eventLine);
  Profiler profiler = new Profiler("CALL_NOTIFICATION_FOR_LINE_ITEM");
  profiler.setLogger(XLOGGER);

  profiler.start("COPY_STOCK_CARD");
  OrderableLotIdentity identity = OrderableLotIdentity.identityOf(eventLine);
  StockCard card = event.getContext().findCard(identity);
  StockCard copy = card.shallowCopy();

  for (StockCardLineItem line : copy.getLineItems()) {
    StockCardLineItemReason reason = line.getReason();

    if (null != reason) {
      line.setReason(event.getContext().findCardReason(reason.getId()));
    }
  }

  profiler.start("CALCULATE_STOCK_ON_HAND");
  copy.calculateStockOnHand();

  profiler.start("NOTIFY_STOCK_CARD_EDITORS");
  if (copy.getStockOnHand() == 0) {
    stockoutNotifier.notifyStockEditors(copy);
  }

  profiler.stop().log();
  XLOGGER.exit();
}

private void startAmbassadorContainers(Profiler profiler) {
    for (final Map.Entry<String, AmbassadorContainer> address : ambassadorContainers.entrySet()) {

        try {
            // Start any ambassador containers we need
            profiler.start("Ambassador container startup");

            final AmbassadorContainer ambassadorContainer = address.getValue();
            Unreliables.retryUntilSuccess(120, TimeUnit.SECONDS, () -> {

                AMBASSADOR_CREATION_RATE_LIMITER.doWhenReady(() -> {
                    Profiler localProfiler = profiler.startNested("Ambassador container: " + ambassadorContainer.getContainerName());

                    localProfiler.start("Start ambassador container");

                    ambassadorContainer.start();
                });

                return null;
            });
        } catch (Exception e) {
            logger().warn("Exception during ambassador container startup!", e);
        } finally {
            profiler.stop().log();
        }
    }
}

@Test
public void takeScreenshot() {

  AndroidDevice device = getDevices().pollFirst();

  Profiler profiler = new Profiler("screen");
  profiler.start("start");
  BufferedImage image = device.takeScreenshot();
  profiler.stop();
  profiler.print();
  String imagePath = new File(System.getProperty("java.io.tmpdir"),
      "screenshot.png").getAbsolutePath();
  ImageUtils.writeToFile(image, imagePath);
  logger.debug("image saved to path {}", imagePath);
}

public void merge ()
{
    this.data = new WritableSeriesData ();

    if ( this.width <= 0 || this.startTimestamp >= this.endTimestamp )
    {
        logger.debug ( "Skip merge - width: {}, start: {}, end: {}", this.width, this.startTimestamp, this.endTimestamp );
        return;
    }

    final Profiler p = new Profiler ( "Merge" ); //$NON-NLS-1$
    p.setLogger ( logger );

    final long start = System.currentTimeMillis ();

    try
    {
        p.start ( "Init" ); //$NON-NLS-1$
        final Entry[] data = new Entry[this.width];

        final long diff = this.endTimestamp - this.startTimestamp;
        final double step = (double)diff / (double)this.width;
        double c = 0.0;

        for ( int i = 0; i < data.length; i++ )
        {
            data[i] = new Entry ();
            data[i].timestamp = this.startTimestamp + (long)c;
            c += step;
        }

        p.start ( "Perform merge" ); //$NON-NLS-1$
        performMerge ( data, step );

        p.start ( "Convert" ); //$NON-NLS-1$
        for ( final Entry entry : data )
        {
            this.data.add ( new DataEntry ( entry.timestamp, entry.value ) );
        }
    }
    catch ( final Exception e )
    {
        logger.warn ( "Failed to merge data", e ); //$NON-NLS-1$
    }
    finally
    {
        p.stop ();

        final boolean tooLong = System.currentTimeMillis () - start > 10 * 1000;

        if ( tooLong || logger.isTraceEnabled () )
        {
            p.log ();
        }
    }
}

@Override
public Query createQuery ( final Session session, final String itemId, final QueryParameters parameters, final QueryListener listener, final boolean updateData ) throws InvalidSessionException, InvalidItemException
{
    final Profiler p = new Profiler ( "createQuery" );
    p.setLogger ( logger );

    p.start ( "Validate session" );
    final SessionImpl sessionImpl = validateSession ( session, SessionImpl.class );

    try
    {
        synchronized ( this )
        {
            p.start ( "Get item" );

            final HistoricalItem item = this.items.get ( itemId );
            if ( item == null )
            {
                throw new InvalidItemException ( itemId );
            }
            p.start ( "new Query" );
            final QueryImpl queryImpl = new QueryImpl ( sessionImpl, listener );
            p.start ( "createQuery" );
            final Query query = item.createQuery ( parameters, queryImpl, updateData );
            p.start ( "Completing" );

            if ( query != null )
            {
                queryImpl.setQuery ( query );
                return queryImpl;
            }
            else
            {
                logger.warn ( "Unable to create query: {}", itemId );
                return null;
            }
        }
    }
    finally
    {
        p.stop ().log ();
    }
}

private void tryStart(Profiler profiler) {
    try {
        String dockerImageName = image.get();
        logger().debug("Starting container: {}", dockerImageName);

        logger().info("Creating container for image: {}", dockerImageName);
        profiler.start("Create container");
        CreateContainerCmd createCommand = dockerClient.createContainerCmd(dockerImageName);
        applyConfiguration(createCommand);
        createContainerCmdModifiers.forEach(hook -> hook.accept(createCommand));

        containerId = createCommand.exec().getId();
        ResourceReaper.instance().registerContainerForCleanup(containerId, dockerImageName);

        logger().info("Starting container with ID: {}", containerId);
        profiler.start("Start container");
        dockerClient.startContainerCmd(containerId).exec();

        // For all registered output consumers, start following as close to container startup as possible
        this.logConsumers.forEach(this::followOutput);

        logger().info("Container {} is starting: {}", dockerImageName, containerId);

        // Tell subclasses that we're starting
        profiler.start("Inspecting container");
        containerInfo = dockerClient.inspectContainerCmd(containerId).exec();
        containerName = containerInfo.getName();
        profiler.start("Call containerIsStarting on subclasses");
        containerIsStarting(containerInfo);

        // Wait until the container is running (may not be fully started)
        profiler.start("Wait until container has started properly, or there's evidence it failed to start.");

        if (!this.startupCheckStrategy.waitUntilStartupSuccessful(dockerClient, containerId)) {
            // Bail out, don't wait for the port to start listening.
            // (Exception thrown here will be caught below and wrapped)
            throw new IllegalStateException("Container did not start correctly.");
        }

        profiler.start("Wait until container started properly");
        waitUntilContainerStarted();

        logger().info("Container {} started", dockerImageName);
        containerIsStarted(containerInfo);
    } catch (Exception e) {
        logger().error("Could not start container", e);

        // Log output if startup failed, either due to a container failure or exception (including timeout)
        logger().error("Container log output (if any) will follow:");
        FrameConsumerResultCallback resultCallback = new FrameConsumerResultCallback();
        resultCallback.addConsumer(STDOUT, new Slf4jLogConsumer(logger()));
        resultCallback.addConsumer(STDERR, new Slf4jLogConsumer(logger()));
        dockerClient.logContainerCmd(containerId).withStdOut(true).withStdErr(true).exec(resultCallback);

        // Try to ensure that container log output is shown before proceeding
        try {
            resultCallback.getCompletionLatch().await(1, TimeUnit.MINUTES);
        } catch (InterruptedException ignored) {
            // Cannot do anything at this point
        }

        throw new ContainerLaunchException("Could not create/start container", e);
    } finally {
        profiler.stop();
    }
}

@Override
protected final String resolve() {
    Logger logger = DockerLoggerFactory.getLogger(dockerImageName);

    Profiler profiler = new Profiler("Rule creation - build image");
    profiler.setLogger(logger);

    DockerClient dockerClient = DockerClientFactory.instance().client();
    try {
        if (deleteOnExit) {
            imagesToDelete.add(dockerImageName);
        }

        BuildImageResultCallback resultCallback = new BuildImageResultCallback() {
            @Override
            public void onNext(BuildResponseItem item) {
                super.onNext(item);

                if (item.isErrorIndicated()) {
                    logger.error(item.getErrorDetail().getMessage());
                } else {
                    logger.debug(StringUtils.chomp(item.getStream(), "\n"));
                }
            }
        };

        // We have to use pipes to avoid high memory consumption since users might want to build really big images
        @Cleanup PipedInputStream in = new PipedInputStream();
        @Cleanup PipedOutputStream out = new PipedOutputStream(in);

        profiler.start("Configure image");
        BuildImageCmd buildImageCmd = dockerClient.buildImageCmd(in);
        configure(buildImageCmd);

        profiler.start("Build image");
        BuildImageResultCallback exec = buildImageCmd.exec(resultCallback);

        // To build an image, we have to send the context to Docker in TAR archive format
        profiler.start("Send context as TAR");

        try (TarArchiveOutputStream tarArchive = new TarArchiveOutputStream(new GZIPOutputStream(out))) {
            tarArchive.setLongFileMode(TarArchiveOutputStream.LONGFILE_POSIX);

            for (Map.Entry<String, Transferable> entry : transferables.entrySet()) {
                Transferable transferable = entry.getValue();
                final String destination = entry.getKey();
                transferable.transferTo(tarArchive, destination);
            }
            tarArchive.finish();
        }

        profiler.start("Wait for an image id");
        exec.awaitImageId();

        return dockerImageName;
    } catch(IOException e) {
        throw new RuntimeException("Can't close DockerClient", e);
    } finally {
        profiler.stop().log();
    }
}

/**
 * 組字而且畫出來。
 * 
 * @param 組字式
 *            使用者要求的組字式
 * @param 欲畫的所在
 *            畫字體的所在
 * @return 實際畫的組字式
 */
public String 組字(String 組字式, Graphics 欲畫的所在)
{
    if (組字式.length() >= 組字式上大長度)
        組字式 = 組字式.substring(0, 組字式上大長度);
    Profiler 看時工具 = new Profiler("組字 " + 組字式);
    看時工具.setLogger(記錄工具);

    看時工具.start("初使化");
    // 記錄工具.debug(MarkerFactory.getMarker("@@"),
    // "初使化～～ 時間：" + System.currentTimeMillis());

    看時工具.start("分析中");
    // 記錄工具.debug("分析中～～ 時間：" + System.currentTimeMillis());

    IDSParser 序列分析工具 = new IDSParser(組字式, 查詢方式);
    CharComponent CharComponent;
    try
    {
        CharComponent = 序列分析工具.解析一個組字式();
    }
    catch (IDSExecption e)
    {
        // TODO 看欲按怎處理，硬顯示，抑是傳連結毋著？
        e.printStackTrace();
        return "";
    }

    CharComponent 組字部件 = (CharComponent) CharComponent;
    // 組字部件.建立組字式(組字式建立工具);
    // 記錄工具.debug(組字部件.提到組字式());
    CharComponent = (CharComponent) 正規化工具.正規化(代換工具.三元素組合代換成二元素(CharComponent));
    組字部件.樹狀結構組字式();
    // 記錄工具.debug(組字部件.提到組字式());

    看時工具.start("設定中");
    // 記錄工具.debug("設定中～～ 時間：" + System.currentTimeMillis());

    ChineseCharCompositeMoveabletype 活字 = CharComponent.typeset(設定工具, null);

    看時工具.start("調整中");
    // 記錄工具.debug("調整中～～ 時間：" + System.currentTimeMillis());

    活字.adjust(調整工具);

    看時工具.start("四角中");
    SeprateMovabletype 上尾欲畫的圖 = 調整工具.format((PieceMovableType) 活字);

    看時工具.start("加粗中");
    活字加粗.加粗(上尾欲畫的圖);

    看時工具.start("列印中");
    // 記錄工具.debug("列印中～～ 時間：" + System.currentTimeMillis());
    Graphics2D 字型圖版 = (Graphics2D) 欲畫的所在;
    字型圖版.setColor(Color.black);
    字型圖版.setRenderingHint(RenderingHints.KEY_ANTIALIASING,
            RenderingHints.VALUE_ANTIALIAS_ON);
    字型圖版.translate(0, 字型大細 * 0.83);// TODO 閣愛研究按怎調整
    字型圖版.setStroke(new NullStroke());

    AwtForSinglePiecePrinter 列印工具 = new AwtForSinglePiecePrinter(字型圖版);

    列印工具.printPiece(上尾欲畫的圖);

    看時工具.stop().log();
    return 組字部件.樹狀結構組字式();
}