Skip to content
Permalink
Browse files

ZOOKEEPER-3019: add metric for slow fsyncs count

Added metric to count fsyncWarningThresholdMS exceed in FileTxnLog.commit(). Both jmx bean and Command can be used to get the stat.

Also updated the python standalone client and documentation.

Tested the py script, i.e.:
src/contrib/monitoring/check_zookeeper.py -o cacti -s "localhost:2181" -k zk_num_alive_connections
localhost_2181:1

rc/contrib/monitoring/check_zookeeper.py -o cacti -s "localhost:2181" -k zk_fsync_threshold_exceed_count
localhost_2181:0

mntr command now returns:
zk_version	3.6.0-SNAPSHOT-13c9f899ff62be6a2eacb28e522d06703f1dab08, built on 04/04/2018 12:09 GMT
zk_avg_latency	0
zk_max_latency	0
zk_min_latency	0
zk_packets_received	7
zk_packets_sent	6
zk_num_alive_connections	1
zk_outstanding_requests	0
zk_server_state	standalone
zk_znode_count	5
zk_watch_count	0
zk_ephemerals_count	0
zk_approximate_data_size	44
zk_open_file_descriptor_count	61
zk_max_file_descriptor_count	10240
zk_fsync_threshold_exceed_count	0

Author: Norbert Kalmar <nkalmar@yahoo.com>

Reviewers: Andor Molnar <andor@apache.org>

Closes #501 from nkalmar/ZOOKEEPER-3019 and squashes the following commits:

067edf6 [Norbert Kalmar] ZOOKEEPER-3019 remove redundant log
7430dbc [Norbert Kalmar] ZOOKEEPER-3019 remove metric from 4ltr command as no longer supported
1916a41 [Norbert Kalmar] ZOOKEEPER-3019 add extra warning log
761450f [Norbert Kalmar] ZOOKEEPER-3019 remove fsync from py script stat check
3b22bb7 [Norbert Kalmar] ZOOKEEPER-3019 remove fsyncEsceed from stats
0be003a [Norbert Kalmar] ZOOKEEPER-3019 exclude serverStats IS chec from findbugs
b48d295 [Norbert Kalmar] ZOOKEEPER-3019 add unit test and fix PR comments
fb4c7a3 [Norbert Kalmar] ZOOKEEPER-3019 add metric to track slow fsyncs count + update py script and docs
  • Loading branch information
nkalmar authored and anmolnar committed Jun 8, 2018
1 parent a35690c commit a2623a625a4778720f7d5482d0a66e9b37ae556f
@@ -230,6 +230,8 @@ xmlns:cs="antlib:com.puppycrawl.tools.checkstyle.ant">
<property name="javadoc-jar" value="${dist.maven.dir}/${final.name}-javadoc.jar"/>


<property name="hamcrest.version" value="1.3"/>

<!-- ====================================================== -->
<!-- Macro definitions -->
<!-- ====================================================== -->
@@ -136,6 +136,9 @@

<dependency org="org.openclover" name="clover" rev="${clover.version}" conf="clover->default"/>

<dependency org="org.hamcrest" name="hamcrest-all" rev="${hamcrest.version}"
conf="test->default" />

<conflict manager="strict"/>

</dependencies>
@@ -26,6 +26,7 @@ zk_max_latency 1788
zk_min_latency 0
zk_packets_received 385466
zk_packets_sent 435364
zk_num_alive_connections 1
zk_outstanding_requests 0
zk_server_state follower
zk_znode_count 5
@@ -241,6 +241,11 @@ def _parse_stat(self, data):
result['zk_packets_sent'] = int(m.group(1))
continue

m = re.match('Alive connections: (\d+)', line)
if m is not None:
result['zk_num_alive_connections'] = int(m.group(1))
continue

m = re.match('Outstanding: (\d+)', line)
if m is not None:
result['zk_outstanding_requests'] = int(m.group(1))
@@ -256,6 +261,31 @@ def _parse_stat(self, data):
result['zk_znode_count'] = int(m.group(1))
continue

m = re.match('Watch count: (\d+)', line)
if m is not None:
result['zk_watch_count'] = int(m.group(1))
continue

m = re.match('Ephemerals count: (\d+)', line)
if m is not None:
result['zk_ephemerals_count'] = int(m.group(1))
continue

m = re.match('Approximate data size: (\d+)', line)
if m is not None:
result['zk_approximate_data_size'] = int(m.group(1))
continue

m = re.match('Open file descriptor count: (\d+)', line)
if m is not None:
result['zk_open_file_descriptor_count'] = int(m.group(1))
continue

m = re.match('Max file descriptor count: (\d+)', line)
if m is not None:
result['zk_max_file_descriptor_count'] = int(m.group(1))
continue

m = re.match('Zxid: (0x[0-9a-fA-F]+)', line)
if m is not None:
result['zk_zxid'] = m.group(1)
@@ -35,6 +35,7 @@ collection_group {
metric { name = "zk_min_latency" }
metric { name = "zk_packets_received" }
metric { name = "zk_packets_sent" }
metric { name = "zk_num_alive_connections" }
metric { name = "zk_outstanding_requests" }
metric { name = "zk_znode_count" }
metric { name = "zk_watch_count" }
@@ -204,6 +204,7 @@ def metric_init(params=None):
'value_type': 'double',
'format': '%f'
},
'zk_num_alive_connections': {'units': 'connections'},
'zk_outstanding_requests': {'units': 'connections'},
'zk_znode_count': {'units': 'znodes'},
'zk_watch_count': {'units': 'watches'},
@@ -1921,6 +1921,7 @@ server.3=zoo3:2888:3888</programlisting>
zk_min_latency 0
zk_packets_received 70
zk_packets_sent 69
zk_num_alive_connections 1
zk_outstanding_requests 0
zk_server_state leader
zk_znode_count 4
@@ -22,6 +22,8 @@

import org.apache.zookeeper.common.Time;

import java.util.concurrent.atomic.AtomicLong;

/**
* Basic Server Statistics
*/
@@ -32,6 +34,7 @@
private long minLatency = Long.MAX_VALUE;
private long totalLatency = 0;
private long count = 0;
private AtomicLong fsyncThresholdExceedCount = new AtomicLong(0);

private final Provider provider;

@@ -148,6 +151,19 @@ synchronized public void resetRequestCounters(){
packetsReceived = 0;
packetsSent = 0;
}

public long getFsyncThresholdExceedCount() {
return fsyncThresholdExceedCount.get();
}

public void incrementFsyncThresholdExceedCount() {
fsyncThresholdExceedCount.incrementAndGet();
}

public void resetFsyncThresholdExceedCount() {
fsyncThresholdExceedCount.set(0);
}

synchronized public void reset() {
resetLatency();
resetRequestCounters();
@@ -153,6 +153,7 @@ public ZooKeeperServer(FileTxnSnapLog txnLogFactory, int tickTime,
int minSessionTimeout, int maxSessionTimeout, ZKDatabase zkDb) {
serverStats = new ServerStats(this);
this.txnLogFactory = txnLogFactory;
this.txnLogFactory.setServerStats(this.serverStats);
this.zkDb = zkDb;
this.tickTime = tickTime;
setMinSessionTimeout(minSessionTimeout);
@@ -127,6 +127,10 @@ public long getPacketsReceived() {
public long getPacketsSent() {
return zks.serverStats().getPacketsSent();
}

public long getFsyncThresholdExceedCount() {
return zks.serverStats().getFsyncThresholdExceedCount();
}

public void resetLatency() {
zks.serverStats().resetLatency();
@@ -136,10 +140,15 @@ public void resetMaxLatency() {
zks.serverStats().resetMaxLatency();
}

public void resetFsyncThresholdExceedCount() {
zks.serverStats().resetFsyncThresholdExceedCount();
}

public void resetStatistics() {
ServerStats serverStats = zks.serverStats();
serverStats.resetRequestCounters();
serverStats.resetLatency();
serverStats.resetFsyncThresholdExceedCount();
}

public long getNumAliveConnections() {
@@ -54,6 +54,10 @@
* @return number of packets sent so far
*/
public long getPacketsSent();
/**
* @return number of fsync threshold exceeds so far
*/
public long getFsyncThresholdExceedCount();
/**
* @return number of outstanding requests.
*/
@@ -103,6 +107,10 @@
* Reset max latency statistics only.
*/
public void resetMaxLatency();
/**
* Reset Fsync Threshold Exceed Count statistics only.
*/
public void resetFsyncThresholdExceedCount();
/**
* @return number of alive client connections
*/
@@ -124,6 +124,7 @@ public void runFromConfig(ServerConfig config)
txnLog = new FileTxnSnapLog(config.dataLogDir, config.dataDir);
final ZooKeeperServer zkServer = new ZooKeeperServer(txnLog,
config.tickTime, config.minSessionTimeout, config.maxSessionTimeout, null);
txnLog.setServerStats(zkServer.serverStats());

// Registers shutdown handler which will be used to know the
// server error or shutdown state changes.
@@ -290,6 +290,7 @@ public CommandResponse run(ZooKeeperServer zkServer, Map<String, String> kwargs)
* - "approximate_data_size": Long
* - "open_file_descriptor_count": Long (unix only)
* - "max_file_descritpor_count": Long (unix only)
* - "fsync_threshold_exceed_count": Long
* - "followers": Integer (leader only)
* - "synced_followers": Integer (leader only)
* - "pending_syncs": Integer (leader only)
@@ -41,6 +41,7 @@
import org.apache.jute.InputArchive;
import org.apache.jute.OutputArchive;
import org.apache.jute.Record;
import org.apache.zookeeper.server.ServerStats;
import org.apache.zookeeper.server.util.SerializeUtils;
import org.apache.zookeeper.txn.TxnHeader;
import org.slf4j.Logger;
@@ -124,6 +125,8 @@
File logFileWrite = null;
private FilePadding filePadding = new FilePadding();

private ServerStats serverStats;

private volatile long syncElapsedMS = -1L;

/**
@@ -144,6 +147,15 @@ public static void setPreallocSize(long size) {
FilePadding.setPreallocSize(size);
}

/**
* Setter for ServerStats to monitor fsync threshold exceed
* @param serverStats used to update fsyncThresholdExceedCount
*/
@Override
public void setServerStats(ServerStats serverStats) {
this.serverStats = serverStats;
}

/**
* creates a checksum algorithm to be used
* @return the checksum used for this txnlog
@@ -320,6 +332,9 @@ public synchronized void commit() throws IOException {

syncElapsedMS = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startSyncNS);
if (syncElapsedMS > fsyncWarningThresholdMS) {
if(serverStats != null) {
serverStats.incrementFsyncThresholdExceedCount();
}
LOG.warn("fsync-ing the write ahead log in "
+ Thread.currentThread().getName()
+ " took " + syncElapsedMS
@@ -33,6 +33,7 @@
import org.apache.zookeeper.server.DataTree;
import org.apache.zookeeper.server.DataTree.ProcessTxnResult;
import org.apache.zookeeper.server.Request;
import org.apache.zookeeper.server.ServerStats;
import org.apache.zookeeper.server.ZooTrace;
import org.apache.zookeeper.server.persistence.TxnLog.TxnIterator;
import org.apache.zookeeper.txn.CreateSessionTxn;
@@ -151,6 +152,10 @@ public FileTxnSnapLog(File dataDir, File snapDir) throws IOException {
ZOOKEEPER_DB_AUTOCREATE_DEFAULT));
}

public void setServerStats(ServerStats serverStats) {
txnLog.setServerStats(serverStats);
}

private void checkLogDir() throws LogDirContentCheckException {
File[] files = this.dataDir.listFiles(new FilenameFilter() {
@Override
@@ -205,7 +210,7 @@ public File getSnapDir() {
* @throws IOException
*/
public long restore(DataTree dt, Map<Long, Integer> sessions,
PlayBackListener listener) throws IOException {
PlayBackListener listener) throws IOException {
long deserializeResult = snapLog.deserialize(dt, sessions);
FileTxnLog txnLog = new FileTxnLog(dataDir);
boolean trustEmptyDB;
@@ -21,13 +21,20 @@
import java.io.IOException;

import org.apache.jute.Record;
import org.apache.zookeeper.server.ServerStats;
import org.apache.zookeeper.txn.TxnHeader;

/**
* Interface for reading transaction logs.
*
*/
public interface TxnLog {

/**
* Setter for ServerStats to monitor fsync threshold exceed
* @param serverStats used to update fsyncThresholdExceedCount
*/
void setServerStats(ServerStats serverStats);

/**
* roll the current
@@ -86,6 +86,11 @@
<Field name="lastProposed"/>
<Bug code="IS"/>
</Match>
<Match>
<Class name="org.apache.zookeeper.server.persistence.FileTxnLog"/>
<Field name="serverStats"/>
<Bug code="IS"/>
</Match>
<Match>
<Class name="org.apache.zookeeper.server.quorum.LearnerSessionTracker"/>
<Bug code="UrF"/>

10 comments on commit a2623a6

@maoling

This comment has been minimized.

Copy link
Contributor

maoling replied Jul 29, 2018

@nkalmar Could you plz create a JIRA to document this metric zk_fsync_threshold_exceed_count in the part of mntr of zookeeperAdmin.html

@nkalmar

This comment has been minimized.

Copy link
Contributor Author

nkalmar replied Jul 30, 2018

@maoling It has been intentionally removed from 3.6 and 3.5, as I was told the 4 letter words is deprecated, and it will be removed. No new metrics should be introduced. Only in 3.4.

@maoling

This comment has been minimized.

Copy link
Contributor

maoling replied Jul 30, 2018

@nkalmar
Thanks for your ACK. 4 letter words will be deprecated? why?

@anmolnar

This comment has been minimized.

Copy link
Contributor

anmolnar replied Jul 30, 2018

Insecure. JMX and Jetty are the future for 3.5+
JMX is also questionable. Not sure if we could drop that too.

@maoling

This comment has been minimized.

Copy link
Contributor

maoling replied Aug 1, 2018

@anmolnar
Sir, Could you plz tell me why the 4 letter words is insecure?

@nkalmar

This comment has been minimized.

Copy link
Contributor Author

nkalmar replied Aug 1, 2018

@maoling , the problem is, there is no security implemented. Any user who can access ZooKeeper (client port), can send commands to the ensemble. While all 4ltw commands is read-only, some takes quite some time, so a DOS attack is actually possible.

So it has been deemed unsecure and deprecated, as far as I know. Originally I implemented the 4ltw command for this PR but the I was suggested to remove from 3.6 and 3.5

@maoling

This comment has been minimized.

Copy link
Contributor

maoling replied Aug 1, 2018

@nkalmar Thanks for your nice explain.
these security problems can also exist in the JMX and Jetty?

@nkalmar

This comment has been minimized.

Copy link
Contributor Author

nkalmar replied Aug 2, 2018

Both JMX and Jetty can be secured. The problem here is, as of my understanding, is that 4ltw command uses the client port. You can secure JMX port, introduce authentication, SSL etc. But you cannot secure the client port like that. So leaving the port open, and the ability to call functions without any authentication or authorization via telnet is not the best practice.

By the way, JMX port should only be open on the local machine, as it is the default setting on ZooKeeper. But if you wan't to open it, it should be secured with firewall/gateway settings, IP restrictions, SASL or whatever.

Jetty can be also configured for SSL.

@maoling

This comment has been minimized.

Copy link
Contributor

maoling replied Aug 2, 2018

wonderful explain.thanks @nkalmar

@anmolnar

This comment has been minimized.

Copy link
Contributor

anmolnar replied Aug 6, 2018

@maoling Trying to find the best email thread in MarkMail for you, but @nkalmar gave you a very good reasoning. It's a long outstanding initiative in the community with a bunch of Jiras involved:
https://issues.apache.org/jira/browse/ZOOKEEPER-2693
https://issues.apache.org/jira/browse/ZOOKEEPER-1346

Please sign in to comment.
You can’t perform that action at this time.