Java tutorial
/** * Licensed to the Apache Software Foundation (ASF) under one * or more contributor license agreements. See the NOTICE file * distributed with this work for additional information * regarding copyright ownership. The ASF licenses this file * to you under the Apache License, Version 2.0 (the * "License"); you may not use this file except in compliance * with the License. You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ package org.apache.htrace.impl; import static java.nio.file.StandardOpenOption.APPEND; import static java.nio.file.StandardOpenOption.CREATE; import static java.nio.file.StandardOpenOption.WRITE; import java.io.IOException; import java.io.RandomAccessFile; import java.nio.ByteBuffer; import java.nio.channels.FileChannel; import java.nio.channels.FileLock; import java.nio.charset.StandardCharsets; import java.nio.file.attribute.PosixFilePermission; import java.nio.file.Files; import java.nio.file.FileSystems; import java.nio.file.Paths; import java.nio.file.StandardOpenOption; import java.text.SimpleDateFormat; import java.util.Date; import java.util.HashSet; import java.util.Set; import java.util.TimeZone; import java.util.concurrent.TimeUnit; import java.util.concurrent.locks.Condition; import java.util.concurrent.locks.ReentrantLock; import org.apache.htrace.core.HTraceConfiguration; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; import org.apache.htrace.core.Span; import org.apache.htrace.core.SpanReceiver; /** * The SpanReceiver which sends spans to htraced. * * HTracedSpanReceiver sends trace spans out to the htraced daemon, where they * are stored and indexed. It supports two forms of RPC: a JSON/HTTP form, and * an HRPC/msgpack form. We will use the msgpack form when * htraced.receiver.packed is set to true. * * HTraced buffers are several megabytes in size, and we reuse them to avoid * creating extra garbage on the heap. They are flushed whenever a timeout * elapses, or when they get more than a configurable percent full. We allocate * two buffers so that we can continue filling one buffer while the other is * being sent over the wire. The buffers store serialized spans. This is * better than storing references to span objects because it minimzes the amount * of pointers we have to follow during a GC. Buffers are managed by instances * of BufferManager. */ public class HTracedSpanReceiver extends SpanReceiver { private static final Log LOG = LogFactory.getLog(HTracedSpanReceiver.class); private final static int MAX_CLOSING_WAIT_MS = 120000; private final FaultInjector faultInjector; private final Conf conf; private final ReentrantLock lock = new ReentrantLock(); private final Condition wakePostSpansThread = lock.newCondition(); private final BufferManager bufferManager[] = new BufferManager[2]; private final RateLimitedLogger flushErrorLog; private final RateLimitedLogger spanDropLog; private final PostSpansThread thread; private boolean shutdown = false; private int activeBuf = 0; private int flushingBuf = -1; private long lastBufferClearedTimeMs = 0; private long unbufferableSpans = 0; private static final SimpleDateFormat ISO_DATE_FORMAT; private static final Set<PosixFilePermission> DROPPED_SPANS_FILE_PERMS; static { ISO_DATE_FORMAT = new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss.SSS"); ISO_DATE_FORMAT.setTimeZone(TimeZone.getTimeZone("UTC")); if (FileSystems.getDefault().supportedFileAttributeViews().contains("posix")) { DROPPED_SPANS_FILE_PERMS = new HashSet<PosixFilePermission>(); DROPPED_SPANS_FILE_PERMS.add(PosixFilePermission.OWNER_READ); DROPPED_SPANS_FILE_PERMS.add(PosixFilePermission.OWNER_WRITE); DROPPED_SPANS_FILE_PERMS.add(PosixFilePermission.GROUP_READ); DROPPED_SPANS_FILE_PERMS.add(PosixFilePermission.GROUP_WRITE); DROPPED_SPANS_FILE_PERMS.add(PosixFilePermission.OTHERS_READ); DROPPED_SPANS_FILE_PERMS.add(PosixFilePermission.OTHERS_WRITE); } else { DROPPED_SPANS_FILE_PERMS = null; } } static class FaultInjector { static FaultInjector NO_OP = new FaultInjector(); public void handleContentLengthTrigger(int len) { } public void handleThreadStart() throws Exception { } public void handleFlush() throws IOException { } } public HTracedSpanReceiver(HTraceConfiguration c) throws Exception { this(c, FaultInjector.NO_OP); } HTracedSpanReceiver(HTraceConfiguration c, FaultInjector faultInjector) throws Exception { this.faultInjector = faultInjector; this.conf = new Conf(c); if (this.conf.packed) { for (int i = 0; i < bufferManager.length; i++) { bufferManager[i] = new PackedBufferManager(conf); } } else { for (int i = 0; i < bufferManager.length; i++) { bufferManager[i] = new RestBufferManager(conf); } } this.flushErrorLog = new RateLimitedLogger(LOG, conf.errorLogPeriodMs); this.spanDropLog = new RateLimitedLogger(LOG, conf.errorLogPeriodMs); this.thread = new PostSpansThread(); LOG.debug("Created new HTracedSpanReceiver with " + conf.toString()); } @Override public void receiveSpan(Span span) { long startTimeMs = 0; int numTries = 1; while (true) { lock.lock(); try { if (shutdown) { LOG.info("Unable to add span because HTracedSpanReceiver is shutting down."); return; } Throwable exc = null; try { bufferManager[activeBuf].writeSpan(span); int contentLength = bufferManager[activeBuf].contentLength(); if (contentLength > conf.triggerSize) { if (LOG.isDebugEnabled()) { LOG.debug("Triggering buffer #" + activeBuf + " flush because" + " buffer contains " + contentLength + " bytes, and " + "triggerSize is " + conf.triggerSize); } faultInjector.handleContentLengthTrigger(contentLength); wakePostSpansThread.signal(); } return; } catch (Exception e) { exc = e; } catch (Error e) { exc = e; } if (startTimeMs == 0) { startTimeMs = TimeUtil.nowMs(); } long deltaMs = TimeUtil.deltaMs(startTimeMs, TimeUtil.nowMs()); if (deltaMs > conf.spanDropTimeoutMs) { StringBuilder bld = new StringBuilder(); spanDropLog.error("Dropping a span after unsuccessfully " + "attempting to add it for " + deltaMs + " ms. There is not " + "enough buffer space. Please increase " + Conf.BUFFER_SIZE_KEY + " or decrease the rate of spans being generated."); unbufferableSpans++; return; } else if (LOG.isDebugEnabled()) { LOG.debug("Unable to write span to buffer #" + activeBuf + " after " + numTries + " attempt(s) and " + deltaMs + " ms" + ". Buffer already has " + bufferManager[activeBuf].getNumberOfSpans() + " spans.", exc); } numTries++; } finally { lock.unlock(); } try { Thread.sleep(conf.spanDropTimeoutMs / 3); } catch (InterruptedException e) { Thread.currentThread().interrupt(); } } } @Override public void close() { lock.lock(); try { shutdown = true; wakePostSpansThread.signal(); } finally { lock.unlock(); } try { thread.join(MAX_CLOSING_WAIT_MS); } catch (InterruptedException e) { LOG.error("HTracedSpanReceiver#close was interrupted", e); Thread.currentThread().interrupt(); } } private class PostSpansThread extends Thread { PostSpansThread() { this.setDaemon(true); this.setName("PostSpans"); this.start(); } private boolean shouldWaitForCond(long timeSinceLastClearedMs) { if (shutdown) { // If we're shutting down, don't wait around. LOG.trace("Should not wait for cond because we're shutting down."); return false; } int contentLength = bufferManager[activeBuf].contentLength(); if (contentLength == 0) { // If there is nothing in the buffer, there is nothing to do. if (LOG.isTraceEnabled()) { LOG.trace("Should wait for cond because we have no data buffered " + "in bufferManager " + activeBuf); } lastBufferClearedTimeMs = TimeUtil.nowMs(); return true; } else if (contentLength >= conf.triggerSize) { // If the active buffer is filling up, start flushing. if (LOG.isDebugEnabled()) { LOG.debug("Should not wait for cond because we have more than " + conf.triggerSize + " bytes buffered in bufferManager " + activeBuf); } return false; } if (timeSinceLastClearedMs > conf.maxFlushIntervalMs) { // If we have let the spans sit in the buffer for too long, // start flushing. if (LOG.isTraceEnabled()) { LOG.trace("Should not wait for cond because it has been " + timeSinceLastClearedMs + " ms since our last flush, and we " + "are overdue for another because maxFlushIntervalMs is " + conf.maxFlushIntervalMs); } return false; } LOG.trace("Should wait for cond."); return true; } @Override public void run() { try { faultInjector.handleThreadStart(); LOG.debug("Starting HTracedSpanReceiver thread for " + conf.endpointStr); BufferManager flushBufManager = null; while (true) { lock.lock(); flushingBuf = -1; try { while (true) { long timeSinceLastClearedMs = TimeUtil.deltaMs(lastBufferClearedTimeMs, TimeUtil.nowMs()); if (!shouldWaitForCond(timeSinceLastClearedMs)) { break; } long waitMs = conf.maxFlushIntervalMs - Math.min(conf.maxFlushIntervalMs, TimeUtil.deltaMs(TimeUtil.nowMs(), lastBufferClearedTimeMs)); if (LOG.isTraceEnabled()) { LOG.trace("Waiting on wakePostSpansThread for " + waitMs + " ms."); } try { wakePostSpansThread.await(waitMs, TimeUnit.MILLISECONDS); } catch (InterruptedException e) { LOG.info("HTraceSpanReceiver thread was interrupted.", e); throw e; } } if (shutdown && (bufferManager[activeBuf].contentLength() == 0)) { LOG.debug("PostSpansThread shutting down."); return; } flushingBuf = activeBuf; flushBufManager = bufferManager[flushingBuf]; activeBuf = (activeBuf == 1) ? 0 : 1; } finally { lock.unlock(); } doFlush(flushBufManager); flushBufManager.clear(); lastBufferClearedTimeMs = TimeUtil.nowMs(); if (LOG.isTraceEnabled()) { LOG.trace("setting lastBufferClearedTimeMs to " + lastBufferClearedTimeMs); } } } catch (Throwable e) { LOG.error("PostSpansThread exiting on unexpected exception", e); } finally { for (int i = 0; i < bufferManager.length; i++) { bufferManager[i].close(); } } } private void doFlush(BufferManager flushBufManager) throws InterruptedException { try { flushBufManager.prepare(); } catch (IOException e) { LOG.error("Failed to prepare buffer containing " + flushBufManager.getNumberOfSpans() + " spans for " + "sending to " + conf.endpointStr + " Discarding " + "all spans.", e); return; } int flushTries = 0; if (unbufferableSpans > 0) { try { appendToDroppedSpansLog( "Dropped " + unbufferableSpans + " spans because of lack of local buffer space.\n"); } catch (IOException e) { // Ignore. We already logged a message about the dropped spans // earlier. } unbufferableSpans = 0; } while (true) { Throwable exc; try { faultInjector.handleFlush(); flushBufManager.flush(); exc = null; } catch (RuntimeException e) { exc = e; } catch (Exception e) { exc = e; } if (exc == null) { return; } int numSpans = flushBufManager.getNumberOfSpans(); flushErrorLog.error("Failed to flush " + numSpans + " htrace " + "spans to " + conf.endpointStr + " on try " + (flushTries + 1), exc); if (flushTries >= conf.flushRetryDelays.length) { StringBuilder bld = new StringBuilder(); bld.append("Failed to flush ").append(numSpans).append(" spans to htraced at") .append(conf.endpointStr).append(" after ").append(flushTries).append(" tries: ") .append(exc.getMessage()).append("\n"); try { appendToDroppedSpansLog(bld.toString()); } catch (IOException e) { bld.append(". Failed to write to dropped spans log: ").append(e.getMessage()); } spanDropLog.error(bld.toString()); return; } int delayMs = conf.flushRetryDelays[flushTries]; Thread.sleep(delayMs); flushTries++; } } } void appendToDroppedSpansLog(String text) throws IOException { // Is the dropped spans log is disabled? if (conf.droppedSpansLogPath.isEmpty() || (conf.droppedSpansLogMaxSize == 0)) { return; } FileLock lock = null; String msg = ISO_DATE_FORMAT.format(new Date()) + ": " + text; ByteBuffer bb = ByteBuffer.wrap(msg.getBytes(StandardCharsets.UTF_8)); // FileChannel locking corresponds to advisory locking on UNIX. It will // protect multiple processes from attempting to write to the same dropped // spans log at once. However, within a single process, we need this // synchronized block to ensure that multiple HTracedSpanReceiver objects // don't try to write to the same log at once. (It is unusal to configure // multiple HTracedSpanReceiver objects, but possible.) synchronized (HTracedSpanReceiver.class) { FileChannel channel = FileChannel.open(Paths.get(conf.droppedSpansLogPath), APPEND, CREATE, WRITE); try { lock = channel.lock(); long size = channel.size(); if (size > conf.droppedSpansLogMaxSize) { throw new IOException("Dropped spans log " + conf.droppedSpansLogPath + " is already " + size + " bytes; will not add to it."); } else if ((size == 0) && (DROPPED_SPANS_FILE_PERMS != null)) { // Set the permissions of the dropped spans file so that other // processes can write to it. Files.setPosixFilePermissions(Paths.get(conf.droppedSpansLogPath), DROPPED_SPANS_FILE_PERMS); } channel.write(bb); } finally { try { if (lock != null) { lock.release(); } } finally { channel.close(); } } } } }