From commits-return-7805-archive-asf-public=cust-asf.ponee.io@zookeeper.apache.org Tue May 21 21:34:46 2019 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [207.244.88.153]) by mx-eu-01.ponee.io (Postfix) with SMTP id CFFB018061A for ; Tue, 21 May 2019 23:34:45 +0200 (CEST) Received: (qmail 97432 invoked by uid 500); 21 May 2019 21:34:45 -0000 Mailing-List: contact commits-help@zookeeper.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@zookeeper.apache.org Delivered-To: mailing list commits@zookeeper.apache.org Received: (qmail 97420 invoked by uid 99); 21 May 2019 21:34:45 -0000 Received: from ec2-52-202-80-70.compute-1.amazonaws.com (HELO gitbox.apache.org) (52.202.80.70) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 21 May 2019 21:34:45 +0000 Received: by gitbox.apache.org (ASF Mail Server at gitbox.apache.org, from userid 33) id EDE2685D86; Tue, 21 May 2019 21:34:44 +0000 (UTC) Date: Tue, 21 May 2019 21:34:44 +0000 To: "commits@zookeeper.apache.org" Subject: [zookeeper] branch master updated: ZOOKEEPER-3323: Add TxnSnapLog metrics MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit Message-ID: <155847448484.31210.590904327527088648@gitbox.apache.org> From: fangmin@apache.org X-Git-Host: gitbox.apache.org X-Git-Repo: zookeeper X-Git-Refname: refs/heads/master X-Git-Reftype: branch X-Git-Oldrev: 6e9802b440b0c706a035a25aafe40b28d25dfadc X-Git-Newrev: d08f51ad1514bfa512597b1ce4bbc2e8144be576 X-Git-Rev: d08f51ad1514bfa512597b1ce4bbc2e8144be576 X-Git-NotificationType: ref_changed_plus_diff X-Git-Multimail-Version: 1.5.dev Auto-Submitted: auto-generated This is an automated email from the ASF dual-hosted git repository. fangmin pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/zookeeper.git The following commit(s) were added to refs/heads/master by this push: new d08f51a ZOOKEEPER-3323: Add TxnSnapLog metrics d08f51a is described below commit d08f51ad1514bfa512597b1ce4bbc2e8144be576 Author: Jie Huang AuthorDate: Tue May 21 14:34:38 2019 -0700 ZOOKEEPER-3323: Add TxnSnapLog metrics Author: Jie Huang Reviewers: anmolnar@apache.org, eolivelli@apache.org, fangmin@apache.org Closes #859 from jhuan31/ZOOKEEPER-3323 --- .../org/apache/zookeeper/server/ServerMetrics.java | 9 +++ .../server/persistence/FileTxnSnapLog.java | 20 ++++- .../persistence/FileTxnSnapLogMetricsTest.java | 93 ++++++++++++++++++++++ 3 files changed, 119 insertions(+), 3 deletions(-) diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/ServerMetrics.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/ServerMetrics.java index 37ffee1..686aacc 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/ServerMetrics.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/ServerMetrics.java @@ -197,6 +197,11 @@ public final class ServerMetrics { */ LEARNER_HANDLER_QP_SIZE = metricsContext.getSummarySet("learner_handler_qp_size", DetailLevel.BASIC); LEARNER_HANDLER_QP_TIME = metricsContext.getSummarySet("learner_handler_qp_time_ms", DetailLevel.ADVANCED); + + STARTUP_TXNS_LOADED = metricsContext.getSummary("startup_txns_loaded", DetailLevel.BASIC); + STARTUP_TXNS_LOAD_TIME = metricsContext.getSummary("startup_txns_load_time", DetailLevel.BASIC); + STARTUP_SNAP_LOAD_TIME = metricsContext.getSummary("startup_snap_load_time", DetailLevel.BASIC); + } /** @@ -274,6 +279,10 @@ public final class ServerMetrics { public final Counter LEARNER_PROPOSAL_RECEIVED_COUNT; public final Counter LEARNER_COMMIT_RECEIVED_COUNT; + public final Summary STARTUP_TXNS_LOADED; + public final Summary STARTUP_TXNS_LOAD_TIME; + public final Summary STARTUP_SNAP_LOAD_TIME; + /** * Fired watcher stats. */ diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/persistence/FileTxnSnapLog.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/persistence/FileTxnSnapLog.java index 7409af8..b0df373 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/persistence/FileTxnSnapLog.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/persistence/FileTxnSnapLog.java @@ -30,11 +30,13 @@ import org.apache.jute.Record; import org.apache.zookeeper.KeeperException; import org.apache.zookeeper.KeeperException.Code; import org.apache.zookeeper.ZooDefs.OpCode; -import org.apache.zookeeper.server.DataTree; -import org.apache.zookeeper.server.DataTree.ProcessTxnResult; -import org.apache.zookeeper.server.Request; +import org.apache.zookeeper.common.Time; +import org.apache.zookeeper.server.ServerMetrics; import org.apache.zookeeper.server.ServerStats; import org.apache.zookeeper.server.ZooTrace; +import org.apache.zookeeper.server.Request; +import org.apache.zookeeper.server.DataTree; +import org.apache.zookeeper.server.DataTree.ProcessTxnResult; import org.apache.zookeeper.server.persistence.TxnLog.TxnIterator; import org.apache.zookeeper.txn.CreateSessionTxn; import org.apache.zookeeper.txn.TxnHeader; @@ -211,7 +213,10 @@ public class FileTxnSnapLog { */ public long restore(DataTree dt, Map sessions, PlayBackListener listener) throws IOException { + long snapLoadingStartTime = Time.currentElapsedTime(); long deserializeResult = snapLog.deserialize(dt, sessions); + ServerMetrics.getMetrics().STARTUP_SNAP_LOAD_TIME.add( + Time.currentElapsedTime() - snapLoadingStartTime); FileTxnLog txnLog = new FileTxnLog(dataDir); boolean trustEmptyDB; File initFile = new File(dataDir.getParent(), "initialize"); @@ -263,6 +268,8 @@ public class FileTxnSnapLog { TxnIterator itr = txnLog.read(dt.lastProcessedZxid+1); long highestZxid = dt.lastProcessedZxid; TxnHeader hdr; + int txnLoaded = 0; + long startTime = Time.currentElapsedTime(); try { while (true) { // iterator points to @@ -280,6 +287,7 @@ public class FileTxnSnapLog { } try { processTransaction(hdr,dt,sessions, itr.getTxn()); + txnLoaded++; } catch(KeeperException.NoNodeException e) { throw new IOException("Failed to process transaction type: " + hdr.getType() + " error: " + e.getMessage(), e); @@ -293,6 +301,12 @@ public class FileTxnSnapLog { itr.close(); } } + + long loadTime = Time.currentElapsedTime() - startTime; + LOG.info("{} txns loaded in {} ms", txnLoaded, loadTime); + ServerMetrics.getMetrics().STARTUP_TXNS_LOADED.add(txnLoaded); + ServerMetrics.getMetrics().STARTUP_TXNS_LOAD_TIME.add(loadTime); + return highestZxid; } diff --git a/zookeeper-server/src/test/java/org/apache/zookeeper/server/persistence/FileTxnSnapLogMetricsTest.java b/zookeeper-server/src/test/java/org/apache/zookeeper/server/persistence/FileTxnSnapLogMetricsTest.java new file mode 100644 index 0000000..4b4ef7a --- /dev/null +++ b/zookeeper-server/src/test/java/org/apache/zookeeper/server/persistence/FileTxnSnapLogMetricsTest.java @@ -0,0 +1,93 @@ +/** + * 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.zookeeper.server.persistence; + +import org.apache.zookeeper.ZooKeeper; +import org.apache.zookeeper.ZooDefs; +import org.apache.zookeeper.ZKTestCase; +import org.apache.zookeeper.Watcher; +import org.apache.zookeeper.WatchedEvent; +import org.apache.zookeeper.CreateMode; +import org.apache.zookeeper.metrics.MetricsUtils; +import org.apache.zookeeper.server.ServerMetrics; +import org.apache.zookeeper.server.SyncRequestProcessor; +import org.apache.zookeeper.test.ClientBase; +import org.apache.zookeeper.test.QuorumUtil; +import org.junit.Assert; +import org.junit.Test; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import java.util.Map; +import java.util.concurrent.CountDownLatch; + +import static org.hamcrest.number.OrderingComparison.greaterThan; +import static org.hamcrest.number.OrderingComparison.greaterThanOrEqualTo; + +public class FileTxnSnapLogMetricsTest extends ZKTestCase { + private static final Logger LOG = LoggerFactory.getLogger(FileTxnSnapLogMetricsTest.class); + + CountDownLatch allCreatedLatch; + + private class MockWatcher implements Watcher { + @Override + public void process(WatchedEvent e) { + LOG.info("all nodes created"); + allCreatedLatch.countDown(); + } + } + + @Test + public void testFileTxnSnapLogMetrics() throws Exception { + SyncRequestProcessor.setSnapCount(100); + + QuorumUtil util = new QuorumUtil(1); + util.startAll(); + + allCreatedLatch = new CountDownLatch(1); + + byte[] data = new byte[500]; + // make sure a snapshot is taken and some txns are not in a snapshot + ZooKeeper zk = ClientBase.createZKClient(util.getConnString()); + for (int i=0; i<150; i++){ + zk.create("/path" + i, data, ZooDefs.Ids.OPEN_ACL_UNSAFE, CreateMode.PERSISTENT); + } + + if (null == zk.exists("/path149", new MockWatcher())) { + allCreatedLatch.await(); + } + + ServerMetrics.getMetrics().resetAll(); + int leader = util.getLeaderServer(); + // restart a server so it will read the snapshot and the txn logs + util.shutdown(leader); + util.start(leader); + + Map values = MetricsUtils.currentServerMetrics(); + LOG.info("txn loaded during start up {}", values.get("max_startup_txns_loaded")); + Assert.assertEquals(1L, values.get("cnt_startup_txns_loaded")); + Assert.assertThat((long)values.get("max_startup_txns_loaded"), greaterThan(0L)); + Assert.assertEquals(1L, values.get("cnt_startup_txns_load_time")); + Assert.assertThat((long)values.get("max_startup_txns_load_time"), greaterThanOrEqualTo(0L)); + Assert.assertEquals(1L, values.get("cnt_startup_snap_load_time")); + Assert.assertThat((long)values.get("max_startup_snap_load_time"), greaterThan(0L)); + + util.shutdownAll(); + } +}