Java tutorial
/* * Copyright 2010 The Apache Software Foundation 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.hadoop.hbase.ipc.bak; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; import org.apache.hadoop.conf.Configuration; import org.apache.hadoop.hbase.HRegionInfo; import org.apache.hadoop.hbase.client.Operation; import org.apache.hadoop.hbase.client.UserProvider; import org.apache.hadoop.hbase.io.HbaseObjectWritable; import org.apache.hadoop.hbase.ipc.VersionedProtocol; import org.apache.hadoop.hbase.monitoring.MonitoredRPCHandler; import org.apache.hadoop.hbase.regionserver.HRegionServer; import org.apache.hadoop.hbase.security.User; import org.apache.hadoop.hbase.util.Bytes; import org.apache.hadoop.hbase.util.Objects; import org.apache.hadoop.io.Writable; import org.apache.hadoop.ipc.RPC; import org.apache.hadoop.security.authorize.ServiceAuthorizationManager; import org.apache.zookeeper.KeeperException; import org.codehaus.jackson.map.ObjectMapper; import java.io.IOException; import java.lang.reflect.*; import java.net.InetSocketAddress; import java.util.HashMap; import java.util.Map; /** An RpcEngine implementation for Writable data. */ class MonitoredRpcEngine implements RpcEngine { // LOG is NOT in hbase subpackage intentionally so that the default HBase // DEBUG log level does NOT emit RPC-level logging. private static final Log LOG = LogFactory.getLog("org.apache.hadoop.ipc.RPCEngine"); private static class Invoker implements InvocationHandler { private Class<? extends VersionedProtocol> protocol; private InetSocketAddress address; private User ticket; private HBaseClient client; final private int rpcTimeout; public Invoker(HBaseClient client, Class<? extends VersionedProtocol> protocol, InetSocketAddress address, User ticket, Configuration conf, int rpcTimeout) { this.protocol = protocol; this.address = address; this.ticket = ticket; this.client = client; this.rpcTimeout = rpcTimeout; } public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { final boolean logDebug = LOG.isDebugEnabled(); long startTime = 0; if (logDebug) { startTime = System.currentTimeMillis(); } HbaseObjectWritable value = (HbaseObjectWritable) client.call(new Invocation(method, protocol, args), address, protocol, ticket, rpcTimeout); if (logDebug) { // FIGURE HOW TO TURN THIS OFF! long callTime = System.currentTimeMillis() - startTime; LOG.debug("Call: " + method.getName() + " " + callTime); } return value.get(); } } private Configuration conf; private HBaseClient client; private UserProvider userProvider; @Override public void setConf(Configuration config) { this.conf = config; // check for an already created client if (this.client != null) { this.client.stop(); } this.client = new HBaseClient(HbaseObjectWritable.class, conf); this.userProvider = UserProvider.instantiate(config); } @Override public Configuration getConf() { return conf; } /** * Construct a client-side proxy object that implements the named protocol, talking to a server at * the named address. */ @Override public <T extends VersionedProtocol> T getProxy(Class<T> protocol, long clientVersion, InetSocketAddress addr, Configuration conf, int rpcTimeout) throws IOException { if (this.client == null) { throw new IOException("Client must be initialized by calling setConf(Configuration)"); } T proxy = (T) Proxy.newProxyInstance(protocol.getClassLoader(), new Class[] { protocol }, new Invoker( client, protocol, addr, userProvider.getCurrent(), conf, HBaseRPC.getRpcTimeout(rpcTimeout))); /* * TODO: checking protocol version only needs to be done once when we setup a new * HBaseClient.Connection. Doing it every time we retrieve a proxy instance is resulting in * unnecessary RPC traffic. */ long serverVersion = ((VersionedProtocol) proxy).getProtocolVersion(protocol.getName(), clientVersion); if (serverVersion != clientVersion) { throw new HBaseRPC.VersionMismatch(protocol.getName(), clientVersion, serverVersion); } return proxy; } /** Expert: Make multiple, parallel calls to a set of servers. */ @Override public Object[] call(Method method, Object[][] params, InetSocketAddress[] addrs, Class<? extends VersionedProtocol> protocol, User ticket, Configuration conf) throws IOException, InterruptedException { if (this.client == null) { throw new IOException("Client must be initialized by calling setConf(Configuration)"); } Invocation[] invocations = new Invocation[params.length]; for (int i = 0; i < params.length; i++) { invocations[i] = new Invocation(method, protocol, params[i]); } Writable[] wrappedValues = client.call(invocations, addrs, protocol, ticket); if (method.getReturnType() == Void.TYPE) { return null; } Object[] values = (Object[]) Array.newInstance(method.getReturnType(), wrappedValues.length); for (int i = 0; i < values.length; i++) { if (wrappedValues[i] != null) { values[i] = ((HbaseObjectWritable) wrappedValues[i]).get(); } } return values; } @Override public void close() { if (this.client != null) { this.client.stop(); } } /** * Construct a server for a protocol implementation instance listening on a port and address. */ public Server getServer(Class<? extends VersionedProtocol> protocol, Object instance, Class<?>[] ifaces, String bindAddress, int port, int numHandlers, int metaHandlerCount, boolean verbose, Configuration conf, int highPriorityLevel) throws IOException { return new Server(instance, ifaces, conf, bindAddress, port, numHandlers, metaHandlerCount, verbose, highPriorityLevel); } /** An RPC Server. */ public static class Server extends HBaseServer implements Schedulable { private Object instance; private Class<?> implementation; private Class<?>[] ifaces; private boolean verbose; private boolean authorize = false; // for JSON encoding private static ObjectMapper mapper = new ObjectMapper(); private static final String WARN_RESPONSE_TIME = "hbase.ipc.warn.response.time"; private static final String WARN_RESPONSE_SIZE = "hbase.ipc.warn.response.size"; /** Default value for above params */ private static final int DEFAULT_WARN_RESPONSE_TIME = 10000; // milliseconds private static final int DEFAULT_WARN_RESPONSE_SIZE = 100 * 1024 * 1024; /** Names for suffixed metrics */ private static final String ABOVE_ONE_SEC_METRIC = ".aboveOneSec."; private final int warnResponseTime; private final int warnResponseSize; private static final String QUEUE_DUMP_INTERVAL = "hbase.ipc.queue.dump.interval"; private static final long DEFAULT_QUEUE_DUMP_INTERVAL = 10 * 1000; private static final String QUEUE_DUMP_ZNODE = "hbase.ipc.queue.dump.znode"; private static final String QUEUE_DUMP_ZNODE_DEDAULT = "/hbase_monitored"; private int maxQueueLength; private SimpleMonitorThread monitor; private static String classNameBase(String className) { String[] names = className.split("\\.", -1); if (names == null || names.length == 0) { return className; } return names[names.length - 1]; } /** * Construct an RPC server. * @param instance the instance whose methods will be called * @param conf the configuration to use * @param bindAddress the address to bind on to listen for connection * @param port the port to listen for connections on * @param numHandlers the number of method handler threads to run * @param verbose whether each call should be logged * @throws java.io.IOException e */ public Server(Object instance, final Class<?>[] ifaces, Configuration conf, String bindAddress, int port, int numHandlers, int metaHandlerCount, boolean verbose, int highPriorityLevel) throws IOException { super(bindAddress, port, Invocation.class, numHandlers, metaHandlerCount, conf, classNameBase(instance.getClass().getName()), highPriorityLevel); LOG.info("Initialize monitored rpc server."); this.instance = instance; this.implementation = instance.getClass(); // this.verbose = verbose; this.verbose = true; this.ifaces = ifaces; // create metrics for the advertised interfaces this server implements. String[] metricSuffixes = new String[] { ABOVE_ONE_SEC_METRIC }; this.rpcMetrics.createMetrics(this.ifaces, false, metricSuffixes); this.authorize = conf.getBoolean(ServiceAuthorizationManager.SERVICE_AUTHORIZATION_CONFIG, false); this.warnResponseTime = conf.getInt(WARN_RESPONSE_TIME, DEFAULT_WARN_RESPONSE_TIME); this.warnResponseSize = conf.getInt(WARN_RESPONSE_SIZE, DEFAULT_WARN_RESPONSE_SIZE); String oldMaxQueueSize = this.conf.get("ipc.server.max.queue.size"); if (oldMaxQueueSize == null) { this.maxQueueLength = this.conf.getInt("ipc.server.max.callqueue.length", numHandlers * 10); } else { LOG.warn("ipc.server.max.queue.size was renamed " + "ipc.server.max.callqueue.length, " + "please update your configuration"); this.maxQueueLength = Integer.getInteger(oldMaxQueueSize); } long interval = conf.getLong(QUEUE_DUMP_INTERVAL, DEFAULT_QUEUE_DUMP_INTERVAL); String zNode = this.conf.get(QUEUE_DUMP_ZNODE, QUEUE_DUMP_ZNODE_DEDAULT); try { monitor = new SimpleMonitorThread(conf, interval, bindAddress, port, zNode, this); } catch (IOException e) { LOG.error("Failed to initialize monitor thread.", e); } } @Override public void start() { super.start(); LOG.info("Starting monitoring thread."); monitor.start(); } @Override public void stop() { LOG.info("Stopping monitoring thread."); if (monitor != null) { monitor.interrupt(); try { monitor.close(); } catch (KeeperException e) { // TODO Auto-generated catch block LOG.error("Error ocuppies when closing monitor thread.", e); } } super.stop(); } @Override public Writable call(Class<? extends VersionedProtocol> protocol, Writable param, long receivedTime, MonitoredRPCHandler status) throws IOException { try { Invocation call = (Invocation) param; if (call.getMethodName() == null) { throw new IOException("Could not find requested method, the usual " + "cause is a version mismatch between client and server."); } if (verbose) log("Call: " + call); status.setRPC(call.getMethodName(), call.getParameters(), receivedTime); status.setRPCPacket(param); status.resume("Servicing call"); Method method = protocol.getMethod(call.getMethodName(), call.getParameterClasses()); method.setAccessible(true); // Verify protocol version. // Bypass the version check for VersionedProtocol if (!method.getDeclaringClass().equals(VersionedProtocol.class)) { long clientVersion = call.getProtocolVersion(); ProtocolSignature serverInfo = ((VersionedProtocol) instance).getProtocolSignature( protocol.getCanonicalName(), call.getProtocolVersion(), call.getClientMethodsHash()); long serverVersion = serverInfo.getVersion(); if (serverVersion != clientVersion) { LOG.warn("Version mismatch: client version=" + clientVersion + ", server version=" + serverVersion); throw new RPC.VersionMismatch(protocol.getName(), clientVersion, serverVersion); } } Object impl = null; if (protocol.isAssignableFrom(this.implementation)) { impl = this.instance; } else { throw new HBaseRPC.UnknownProtocolException(protocol); } long startTime = System.currentTimeMillis(); Object[] params = call.getParameters(); Object value = method.invoke(impl, params); int processingTime = (int) (System.currentTimeMillis() - startTime); int qTime = (int) (startTime - receivedTime); // if (TRACELOG.isDebugEnabled()) { TRACELOG.debug("Call #" + CurCall.get().id + "; Served: " + protocol.getSimpleName() + "#" + call.getMethodName() + " queueTime=" + qTime + " processingTime=" + processingTime + " contents=" + Objects.describeQuantity(params)); // } rpcMetrics.rpcQueueTime.inc(qTime); rpcMetrics.rpcProcessingTime.inc(processingTime); rpcMetrics.inc(call.getMethodName(), processingTime); if (verbose) log("Return: " + value); HbaseObjectWritable retVal = new HbaseObjectWritable(method.getReturnType(), value); long responseSize = retVal.getWritableSize(); // log any RPC responses that are slower than the configured warn // response time or larger than configured warning size boolean tooSlow = (processingTime > warnResponseTime && warnResponseTime > -1); boolean tooLarge = (responseSize > warnResponseSize && warnResponseSize > -1); if (tooSlow || tooLarge) { // when tagging, we let TooLarge trump TooSmall to keep output simple // note that large responses will often also be slow. logResponse(call, (tooLarge ? "TooLarge" : "TooSlow"), status.getClient(), startTime, processingTime, qTime, responseSize); // provides a count of log-reported slow responses if (tooSlow) { rpcMetrics.rpcSlowResponseTime.inc(processingTime); } } if (processingTime > 1000) { // we use a hard-coded one second period so that we can clearly // indicate the time period we're warning about in the name of the // metric itself rpcMetrics.inc(call.getMethodName() + ABOVE_ONE_SEC_METRIC, processingTime); } return retVal; } catch (InvocationTargetException e) { Throwable target = e.getTargetException(); if (target instanceof IOException) { throw (IOException) target; } IOException ioe = new IOException(target.toString()); ioe.setStackTrace(target.getStackTrace()); throw ioe; } catch (Throwable e) { if (!(e instanceof IOException)) { LOG.error("Unexpected throwable object ", e); } IOException ioe = new IOException(e.toString()); ioe.setStackTrace(e.getStackTrace()); throw ioe; } } /** * Logs an RPC response to the LOG file, producing valid JSON objects for client Operations. * @param call The call to log. * @param tag The tag that will be used to indicate this event in the log. * @param clientAddress The address of the client who made this call. * @param startTime The time that the call was initiated, in ms. * @param processingTime The duration that the call took to run, in ms. * @param qTime The duration that the call spent on the queue prior to being initiated, in ms. * @param responseSize The size in bytes of the response buffer. */ private void logResponse(Invocation call, String tag, String clientAddress, long startTime, int processingTime, int qTime, long responseSize) throws IOException { Object params[] = call.getParameters(); // for JSON encoding ObjectMapper mapper = new ObjectMapper(); // base information that is reported regardless of type of call Map<String, Object> responseInfo = new HashMap<String, Object>(); responseInfo.put("starttimems", startTime); responseInfo.put("processingtimems", processingTime); responseInfo.put("queuetimems", qTime); responseInfo.put("responsesize", responseSize); responseInfo.put("client", clientAddress); responseInfo.put("class", instance.getClass().getSimpleName()); responseInfo.put("method", call.getMethodName()); if (params.length == 2 && instance instanceof HRegionServer && params[0] instanceof byte[] && params[1] instanceof Operation) { // if the slow process is a query, we want to log its table as well // as its own fingerprint byte[] tableName = HRegionInfo.parseRegionName((byte[]) params[0])[0]; responseInfo.put("table", Bytes.toStringBinary(tableName)); // annotate the response map with operation details responseInfo.putAll(((Operation) params[1]).toMap()); // report to the log file LOG.warn("(operation" + tag + "): " + mapper.writeValueAsString(responseInfo)); } else if (params.length == 1 && instance instanceof HRegionServer && params[0] instanceof Operation) { // annotate the response map with operation details responseInfo.putAll(((Operation) params[0]).toMap()); // report to the log file LOG.warn("(operation" + tag + "): " + mapper.writeValueAsString(responseInfo)); } else { // can't get JSON details, so just report call.toString() along with // a more generic tag. responseInfo.put("call", call.toString()); LOG.warn("(response" + tag + "): " + mapper.writeValueAsString(responseInfo)); } } @Override public String dumpStatus() { rpcMetrics.doUpdates(null); StringBuilder sb = new StringBuilder(); // double full = ( (double) currentCallSize) / maxQueueLength * 100; // String logInfo = String.format("Current call queue size is %d. %.2f full. " , // currentCallSize, full); // LOG.info(logInfo); // int currentPriorityCallSize = priorityCallQueue.size(); // double priorityfull = ( (double) currentPriorityCallSize) / maxQueueLength * 100; // logInfo = String.format("Current priority call queue size is %d. %.2f full. ", // currentPriorityCallSize, priorityfull); // LOG.info(logInfo); // logInfo = String.format("Max queue handler: %d." + // "RPC average priority queue time: %d. " + // "RPC average priority process time: %d." + // "Done %d operations.", // rpcMetrics.callQueueLen.get(), // rpcMetrics.rpcQueueTime.getPreviousIntervalAverageTime(), // rpcMetrics.rpcProcessingTime.getPreviousIntervalAverageTime(), // rpcMetrics.rpcQueueTime.getPreviousIntervalNumOps()); // LOG.info(logInfo); sb.append("maxQueueSize=" + maxQueueLength + "\n"); sb.append("currentCallQueueUsage=" + rpcMetrics.callQueueLen.get() + "\n"); sb.append("currentPriorityQueueUsage=" + rpcMetrics.priorityCallQueueLen.get() + "\n"); sb.append("currentCoprocessorQueueUsage=" + rpcMetrics.coprocessorCallQueueLen.get() + "\n"); sb.append("averageQueueTime=" + rpcMetrics.rpcQueueTime.getPreviousIntervalAverageTime() + "\n"); sb.append("averageProcessTime=" + rpcMetrics.rpcProcessingTime.getPreviousIntervalAverageTime() + "\n"); sb.append("rpcProcessingOps=" + rpcMetrics.rpcProcessingTime.getPreviousIntervalAverageTime() + "\n"); return sb.toString(); } @Override public void schedule(String info) { // TODO Auto-generated method stub } } protected static void log(String value) { String v = value; if (v != null && v.length() > 55) v = v.substring(0, 55) + "..."; LOG.info(v); } }