ZOOKEEPER-443. trace logging in watch notification not wrapped with istraceneabled - inefficient (pat via mahadev)

git-svn-id: https://svn.apache.org/repos/asf/hadoop/zookeeper/trunk@784970 13f79535-47bb-0310-9956-ffa450edef68

CHANGES.txt

@@ -206,6 +206,9 @@ via mahadev)
 
   ZOOKEEPER-437. Variety of Documentation Updates (grant via mahadev)
 
+  ZOOKEEPER-443. trace logging in watch notification not wrapped with
+istraceneabled - inefficient (pat via mahadev)
+
 NEW FEATURES:
 
   ZOOKEEPER-371. jdiff documentation included in build/release (giri via phunt)

src/java/main/org/apache/zookeeper/server/DataTree.java

@@ -512,14 +512,16 @@ public class DataTree {
             updateCount(lastPrefix, -1);
             updateBytes(lastPrefix, node.data == null? 0:-(node.data.length));
         }
-        ZooTrace.logTraceMessage(LOG,
-                                 ZooTrace.EVENT_DELIVERY_TRACE_MASK,
-                                 "dataWatches.triggerWatch " + path);
-        ZooTrace.logTraceMessage(LOG,
-                                 ZooTrace.EVENT_DELIVERY_TRACE_MASK,
-                                 "childWatches.triggerWatch " + parentName);
+        if (LOG.isTraceEnabled()) {
+            ZooTrace.logTraceMessage(LOG,
+                                     ZooTrace.EVENT_DELIVERY_TRACE_MASK,
+                                     "dataWatches.triggerWatch " + path);
+            ZooTrace.logTraceMessage(LOG,
+                                     ZooTrace.EVENT_DELIVERY_TRACE_MASK,
+                                     "childWatches.triggerWatch " + parentName);
+        }
         Set<Watcher> processed =
-        dataWatches.triggerWatch(path, EventType.NodeDeleted);
+            dataWatches.triggerWatch(path, EventType.NodeDeleted);
         childWatches.triggerWatch(path, EventType.NodeDeleted, processed);
         childWatches.triggerWatch(parentName.equals("")?"/":parentName, EventType.NodeChildrenChanged);
     }

src/java/main/org/apache/zookeeper/server/FinalRequestProcessor.java

@@ -78,7 +78,9 @@ public class FinalRequestProcessor implements RequestProcessor {
         if (request.type == OpCode.ping) {
             traceMask = ZooTrace.SERVER_PING_TRACE_MASK;
         }
-        ZooTrace.logRequest(LOG, traceMask, 'E', request, "");
+        if (LOG.isTraceEnabled()) {
+            ZooTrace.logRequest(LOG, traceMask, 'E', request, "");
+        }
         ProcessTxnResult rc = null;
         synchronized (zks.outstandingChanges) {
             while (!zks.outstandingChanges.isEmpty()

src/java/main/org/apache/zookeeper/server/NIOServerCnxn.java

@@ -917,10 +917,12 @@ public class NIOServerCnxn implements Watcher, ServerCnxn {
      */
     synchronized public void process(WatchedEvent event) {
         ReplyHeader h = new ReplyHeader(-1, -1L, 0);
-        ZooTrace.logTraceMessage(LOG, ZooTrace.EVENT_DELIVERY_TRACE_MASK,
-                                 "Deliver event " + event + " to 0x"
-                                 + Long.toHexString(this.sessionId)
-                                 + " through " + this);
+        if (LOG.isTraceEnabled()) {
+            ZooTrace.logTraceMessage(LOG, ZooTrace.EVENT_DELIVERY_TRACE_MASK,
+                                     "Deliver event " + event + " to 0x"
+                                     + Long.toHexString(this.sessionId)
+                                     + " through " + this);
+        }
 
         // Convert WatchedEvent to a type that can be sent over the wire
         WatcherEvent e = event.getWrapper();

src/java/main/org/apache/zookeeper/server/PrepRequestProcessor.java

@@ -97,7 +97,9 @@ public class PrepRequestProcessor extends Thread implements RequestProcessor {
                 if (request.type == OpCode.ping) {
                     traceMask = ZooTrace.CLIENT_PING_TRACE_MASK;
                 }
-                ZooTrace.logRequest(LOG, traceMask, 'P', request, "");
+                if (LOG.isTraceEnabled()) {
+                    ZooTrace.logRequest(LOG, traceMask, 'P', request, "");
+                }
                 if (Request.requestOfDeath == request) {
                     break;
                 }

src/java/main/org/apache/zookeeper/server/SessionTrackerImpl.java

@@ -142,10 +142,12 @@ public class SessionTrackerImpl extends Thread implements SessionTracker {
     }
 
     synchronized public boolean touchSession(long sessionId, int timeout) {
-        ZooTrace.logTraceMessage(LOG,
-                                 ZooTrace.CLIENT_PING_TRACE_MASK,
-                                 "SessionTrackerImpl --- Touch session: 0x"
-                + Long.toHexString(sessionId) + " with timeout " + timeout);
+        if (LOG.isTraceEnabled()) {
+            ZooTrace.logTraceMessage(LOG,
+                                     ZooTrace.CLIENT_PING_TRACE_MASK,
+                                     "SessionTrackerImpl --- Touch session: 0x"
+                    + Long.toHexString(sessionId) + " with timeout " + timeout);
+        }
         Session s = sessionsById.get(sessionId);
         if (s == null) {
             return false;
@@ -172,9 +174,11 @@ public class SessionTrackerImpl extends Thread implements SessionTracker {
     synchronized public void removeSession(long sessionId) {
         Session s = sessionsById.remove(sessionId);
         sessionsWithTimeout.remove(sessionId);
-        ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
-                "SessionTrackerImpl --- Removing session 0x"
-                + Long.toHexString(sessionId));
+        if (LOG.isTraceEnabled()) {
+            ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
+                    "SessionTrackerImpl --- Removing session 0x"
+                    + Long.toHexString(sessionId));
+        }
         if (s != null) {
             sessionSets.get(s.tickTime).sessions.remove(s);
         }
@@ -182,8 +186,10 @@ public class SessionTrackerImpl extends Thread implements SessionTracker {
 
     public void shutdown() {
         running = false;
-        ZooTrace.logTraceMessage(LOG, ZooTrace.getTextTraceLevel(),
-                                 "Shutdown SessionTrackerImpl!");
+        if (LOG.isTraceEnabled()) {
+            ZooTrace.logTraceMessage(LOG, ZooTrace.getTextTraceLevel(),
+                                     "Shutdown SessionTrackerImpl!");
+        }
     }
 
    
@@ -197,13 +203,17 @@ public class SessionTrackerImpl extends Thread implements SessionTracker {
         if (sessionsById.get(id) == null) {
             Session s = new Session(id, 0);
             sessionsById.put(id, s);
-            ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
-                    "SessionTrackerImpl --- Adding session 0x" 
-                    + Long.toHexString(id) + " " + sessionTimeout);
+            if (LOG.isTraceEnabled()) {
+                ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
+                        "SessionTrackerImpl --- Adding session 0x" 
+                        + Long.toHexString(id) + " " + sessionTimeout);
+            }
         } else {
-            ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
-                    "SessionTrackerImpl --- Existing session 0x" 
-                    + Long.toHexString(id) + " " + sessionTimeout);
+            if (LOG.isTraceEnabled()) {
+                ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
+                        "SessionTrackerImpl --- Existing session 0x" 
+                        + Long.toHexString(id) + " " + sessionTimeout);
+            }
         }
         touchSession(id, sessionTimeout);
     }

src/java/main/org/apache/zookeeper/server/WatchManager.java

@@ -88,9 +88,11 @@ public class WatchManager {
         synchronized (this) {
             watchers = watchTable.remove(path);
             if (watchers == null || watchers.isEmpty()) {
-                ZooTrace.logTraceMessage(LOG,
-                        ZooTrace.EVENT_DELIVERY_TRACE_MASK,
-                        "No watchers for " + path);
+                if (LOG.isTraceEnabled()) {
+                    ZooTrace.logTraceMessage(LOG,
+                            ZooTrace.EVENT_DELIVERY_TRACE_MASK,
+                            "No watchers for " + path);
+                }
                 return null;
             }
             for (Watcher w : watchers) {

src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java

@@ -312,9 +312,11 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider {
 
     protected void killSession(long sessionId, long zxid) {
         dataTree.killSession(sessionId, zxid);
-        ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
-                                     "ZooKeeperServer --- killSession: 0x"
-                + Long.toHexString(sessionId));
+        if (LOG.isTraceEnabled()) {
+            ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
+                                         "ZooKeeperServer --- killSession: 0x"
+                    + Long.toHexString(sessionId));
+        }
         if (sessionTracker != null) {
             sessionTracker.removeSession(sessionId);
         }
@@ -502,9 +504,11 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider {
     protected void revalidateSession(ServerCnxn cnxn, long sessionId,
             int sessionTimeout) throws IOException, InterruptedException {
         boolean rc = sessionTracker.touchSession(sessionId, sessionTimeout);
-        ZooTrace.logTraceMessage(LOG,ZooTrace.SESSION_TRACE_MASK,
-                                 "Session 0x" + Long.toHexString(sessionId) +
-                " is valid: " + rc);
+        if (LOG.isTraceEnabled()) {
+            ZooTrace.logTraceMessage(LOG,ZooTrace.SESSION_TRACE_MASK,
+                                     "Session 0x" + Long.toHexString(sessionId) +
+                    " is valid: " + rc);
+        }
         cnxn.finishSessionInit(rc);
     }
 

src/java/main/org/apache/zookeeper/server/persistence/FileTxnSnapLog.java

@@ -155,19 +155,23 @@ public class FileTxnSnapLog {
         case OpCode.createSession:
             sessions.put(hdr.getClientId(),
                     ((CreateSessionTxn) txn).getTimeOut());
-            ZooTrace.logTraceMessage(LOG,ZooTrace.SESSION_TRACE_MASK,
-                    "playLog --- create session in log: "
-                            + Long.toHexString(hdr.getClientId())
-                            + " with timeout: "
-                            + ((CreateSessionTxn) txn).getTimeOut());
+            if (LOG.isTraceEnabled()) {
+                ZooTrace.logTraceMessage(LOG,ZooTrace.SESSION_TRACE_MASK,
+                        "playLog --- create session in log: "
+                                + Long.toHexString(hdr.getClientId())
+                                + " with timeout: "
+                                + ((CreateSessionTxn) txn).getTimeOut());
+            }
             // give dataTree a chance to sync its lastProcessedZxid
             dt.processTxn(hdr, txn);
             break;
         case OpCode.closeSession:
             sessions.remove(hdr.getClientId());
-            ZooTrace.logTraceMessage(LOG,ZooTrace.SESSION_TRACE_MASK,
-                    "playLog --- close session in log: "
-                            + Long.toHexString(hdr.getClientId()));
+            if (LOG.isTraceEnabled()) {
+                ZooTrace.logTraceMessage(LOG,ZooTrace.SESSION_TRACE_MASK,
+                        "playLog --- close session in log: "
+                                + Long.toHexString(hdr.getClientId()));
+            }
             dt.processTxn(hdr, txn);
             break;
         default:

src/java/main/org/apache/zookeeper/server/quorum/Follower.java

@@ -117,7 +117,9 @@ public class Follower {
         if (pp.getType() == Leader.PING) {
             traceMask = ZooTrace.SERVER_PING_TRACE_MASK;
         }
-        ZooTrace.logQuorumPacket(LOG, traceMask, 'i', pp);
+        if (LOG.isTraceEnabled()) {
+            ZooTrace.logQuorumPacket(LOG, traceMask, 'i', pp);
+        }
     }
 
     /**
@@ -291,10 +293,12 @@ public class Follower {
                                 cnxn.finishSessionInit(valid);
                             }
                         }
-                        ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
-                                                 "Session 0x" 
-                                                 + Long.toHexString(sessionId)
-                                                 + " is valid: " + valid);
+                        if (LOG.isTraceEnabled()) {
+                            ZooTrace.logTraceMessage(LOG,
+                                    ZooTrace.SESSION_TRACE_MASK,
+                                    "Session 0x" + Long.toHexString(sessionId)
+                                    + " is valid: " + valid);
+                        }
                         break;
                     case Leader.SYNC:
                         zk.sync();
@@ -350,10 +354,12 @@ public class Follower {
         QuorumPacket qp = new QuorumPacket(Leader.REVALIDATE, -1, baos
                 .toByteArray(), null);
         pendingRevalidations.put(clientId, cnxn);
-        ZooTrace.logTraceMessage(LOG,
-                                 ZooTrace.SESSION_TRACE_MASK,
-                                 "To validate session 0x"
-                                 + Long.toHexString(clientId));
+        if (LOG.isTraceEnabled()) {
+            ZooTrace.logTraceMessage(LOG,
+                                     ZooTrace.SESSION_TRACE_MASK,
+                                     "To validate session 0x"
+                                     + Long.toHexString(clientId));
+        }
         writePacket(qp, true);
     }
 

src/java/main/org/apache/zookeeper/server/quorum/FollowerHandler.java

@@ -120,7 +120,9 @@ public class FollowerHandler extends Thread {
                 if (p.getType() == Leader.PING) {
                     traceMask = ZooTrace.SERVER_PING_TRACE_MASK;
                 }
-                ZooTrace.logQuorumPacket(LOG, traceMask, 'o', p);
+                if (LOG.isTraceEnabled()) {
+                    ZooTrace.logQuorumPacket(LOG, traceMask, 'o', p);
+                }
                 oa.writeRecord(p, "packet");
             } catch (IOException e) {
                 if (!sock.isClosed()) {
@@ -314,7 +316,9 @@ public class FollowerHandler extends Thread {
                 if (qp.getType() == Leader.PING) {
                     traceMask = ZooTrace.SERVER_PING_TRACE_MASK;
                 }
-                ZooTrace.logQuorumPacket(LOG, traceMask, 'i', qp);
+                if (LOG.isTraceEnabled()) {
+                    ZooTrace.logQuorumPacket(LOG, traceMask, 'i', qp);
+                }
                 tickOfLastAck = leader.self.tick;
 
 
@@ -347,10 +351,12 @@ public class FollowerHandler extends Thread {
                     DataOutputStream dos = new DataOutputStream(bos);
                     dos.writeLong(id);
                     boolean valid = leader.zk.touch(id, to);
-                    ZooTrace.logTraceMessage(LOG,
-                                             ZooTrace.SESSION_TRACE_MASK,
-                                             "Session 0x" + Long.toHexString(id)
-                                             + " is valid: "+ valid);
+                    if (LOG.isTraceEnabled()) {
+                        ZooTrace.logTraceMessage(LOG,
+                                                 ZooTrace.SESSION_TRACE_MASK,
+                                                 "Session 0x" + Long.toHexString(id)
+                                                 + " is valid: "+ valid);
+                    }
                     dos.writeBoolean(valid);
                     qp.setData(bos.toByteArray());
                     queuedPackets.add(qp);

src/java/main/org/apache/zookeeper/server/quorum/FollowerRequestProcessor.java

@@ -55,8 +55,10 @@ public class FollowerRequestProcessor extends Thread implements
         try {
             while (!finished) {
                 Request request = queuedRequests.take();
-                ZooTrace.logRequest(LOG, ZooTrace.CLIENT_REQUEST_TRACE_MASK,
-                        'F', request, "");
+                if (LOG.isTraceEnabled()) {
+                    ZooTrace.logRequest(LOG, ZooTrace.CLIENT_REQUEST_TRACE_MASK,
+                            'F', request, "");
+                }
                 if (request == Request.requestOfDeath) {
                     break;
                 }

src/java/main/org/apache/zookeeper/server/upgrade/UpgradeSnapShotV1.java

@@ -88,9 +88,11 @@ public class UpgradeSnapShotV1 implements UpgradeSnapShot {
             long id = ia.readLong("id");
             int to = ia.readInt("timeout");
             sessions.put(id, to);
-            ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
-                    "loadData --- session in archive: " + id
-                    + " with timeout: " + to);
+            if (LOG.isTraceEnabled()) {
+                ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
+                        "loadData --- session in archive: " + id
+                        + " with timeout: " + to);
+            }
             count--;
         }
         oldTree.deserialize(ia, "tree");
@@ -131,21 +133,25 @@ public class UpgradeSnapShotV1 implements UpgradeSnapShot {
                 case OpCode.createSession:
                     sessionsWithTimeouts.put(hdr.getClientId(),
                             ((CreateSessionTxn) txn).getTimeOut());
-                    ZooTrace.logTraceMessage(LOG,
-                                             ZooTrace.SESSION_TRACE_MASK,
-                            "playLog --- create session in log: 0x"
-                                    + Long.toHexString(hdr.getClientId())
-                                    + " with timeout: "
-                                    + ((CreateSessionTxn) txn).getTimeOut());
+                    if (LOG.isTraceEnabled()) {
+                        ZooTrace.logTraceMessage(LOG,
+                                                 ZooTrace.SESSION_TRACE_MASK,
+                                "playLog --- create session in log: 0x"
+                                        + Long.toHexString(hdr.getClientId())
+                                        + " with timeout: "
+                                        + ((CreateSessionTxn) txn).getTimeOut());
+                    }
                     // give dataTree a chance to sync its lastProcessedZxid
                     oldDataTree.processTxn(hdr, txn);
                     break;
                 case OpCode.closeSession:
                     sessionsWithTimeouts.remove(hdr.getClientId());
-                    ZooTrace.logTraceMessage(LOG,
-                            ZooTrace.SESSION_TRACE_MASK,
-                            "playLog --- close session in log: 0x"
-                                    + Long.toHexString(hdr.getClientId()));
+                    if (LOG.isTraceEnabled()) {
+                        ZooTrace.logTraceMessage(LOG,
+                                ZooTrace.SESSION_TRACE_MASK,
+                                "playLog --- close session in log: 0x"
+                                        + Long.toHexString(hdr.getClientId()));
+                    }
                     oldDataTree.processTxn(hdr, txn);
                     break;
                 default:

src/java/main/org/apache/zookeeper/server/util/SerializeUtils.java

@@ -83,9 +83,11 @@ public class SerializeUtils {
             long id = ia.readLong("id");
             int to = ia.readInt("timeout");
             sessions.put(id, to);
-            ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
-                    "loadData --- session in archive: " + id
-                    + " with timeout: " + to);
+            if (LOG.isTraceEnabled()) {
+                ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
+                        "loadData --- session in archive: " + id
+                        + " with timeout: " + to);
+            }
             count--;
         }
         dt.deserialize(ia, "tree");