Skip to content

Commit

Permalink
Fix #518: Add mloginfo --connections support for connection duration …
Browse files Browse the repository at this point in the history 
…metrics (#530)

* Add min/max/avg connection durations with new argument option --connstats.
* Add nosetests for --connstats.
* Add folder connstats to mtools/test/logfiles with more logfiles specific for connstats test.
  • Loading branch information
@sindbach
Nishant Bhardwaj authored and sindbach committed Oct 11, 2017
1 parent f41a2c3 commit 93d7080
Show file tree
Hide file tree
Showing 10 changed files with 399 additions and 3 deletions.
103 changes: 100 additions & 3 deletions mtools/mloginfo/sections/connection_section.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -17,14 +17,14 @@ class ConnectionSection(BaseSection):
def __init__(self, mloginfo):
BaseSection.__init__(self, mloginfo)

# add --restarts flag to argparser
self.mloginfo.argparser_sectiongroup.add_argument('--connections', action='store_true', help='outputs information about opened and closed connections')
self.mloginfo.argparser_sectiongroup.add_argument('--connstats', action='store_true', help='outputs helpful statistics for connection duration (min/max/avg)')


@property
def active(self):
""" return boolean if this section is active. """
return self.mloginfo.args['connections']
return self.mloginfo.args['connections'] or self.mloginfo.args['connstats']


def run(self):
Expand All @@ -37,10 +37,33 @@ def run(self):

ip_opened = defaultdict(lambda: 0)
ip_closed = defaultdict(lambda: 0)

socket_exceptions = 0

START_TIME_EMPTY=-11
END_TIME_ALREADY_FOUND=-111
MIN_DURATION_EMPTY=9999999999
MAX_DURATION_EMPTY=-1

end_connid_pattern = re.compile(r'\[conn(\d+)\]')

genstats = self.mloginfo.args['connstats']
if genstats:
connections_start = defaultdict(lambda: START_TIME_EMPTY)
ipwise_sum_durations = defaultdict(lambda:0)
ipwise_count = defaultdict(lambda:0)
ipwise_min_connection_duration = defaultdict(lambda:MIN_DURATION_EMPTY)
ipwise_max_connection_duration = defaultdict(lambda:MAX_DURATION_EMPTY)

min_connection_duration = MIN_DURATION_EMPTY
max_connection_duration = MAX_DURATION_EMPTY

sum_durations = 0
fullconn_counts = 0

for logevent in self.mloginfo.logfile:
line = logevent.line_str

pos = line.find('connection accepted')
if pos != -1:
# connection was opened, increase counter
Expand All @@ -51,6 +74,20 @@ def run(self):
ip, _ = tokens[3].split(':')
ip_opened[ip] += 1

if genstats:
connid = tokens[4].strip('#')
dt = logevent.datetime

#Sanity checks
if connid.isdigit() == False or dt == None :
continue

if connections_start[connid] != START_TIME_EMPTY:
raise NotImplementedError("Multiple start datetimes found for the same connection ID. Consider analysing one log sequence.")

connections_start[connid] = dt


pos = line.find('end connection')
if pos != -1:
# connection was closed, increase counter
Expand All @@ -61,6 +98,47 @@ def run(self):
ip, _ = tokens[2].split(':')
ip_closed[ip] += 1

if genstats:

#Sanity check
if end_connid_pattern.search(line, re.M | re.I) == None :
continue

#The connection id value is stored just before end connection -> [conn385] end connection
end_connid = end_connid_pattern.search(line, re.M | re.I).group(1)
dt = logevent.datetime

#Sanity checks
if end_connid.isdigit() == False or dt == None or connections_start[end_connid] == START_TIME_EMPTY :
continue

if connections_start[end_connid] == END_TIME_ALREADY_FOUND:
raise NotImplementedError("Multiple end datetimes found for the same connection ID %s. Consider analysing one log sequence." % (end_connid))

dur = dt - connections_start[end_connid]
dur_in_sec = dur.seconds

if dur_in_sec < min_connection_duration:
min_connection_duration = dur_in_sec

if dur_in_sec > max_connection_duration:
max_connection_duration = dur_in_sec

if dur_in_sec < ipwise_min_connection_duration[ip]:
ipwise_min_connection_duration[ip] = dur_in_sec

if dur_in_sec > ipwise_max_connection_duration[ip]:
ipwise_max_connection_duration[ip] = dur_in_sec

sum_durations += dur.seconds
fullconn_counts += 1

ipwise_sum_durations[ip] += dur_in_sec
ipwise_count[ip] += 1

connections_start[end_connid] = END_TIME_ALREADY_FOUND


if "SocketException" in line:
socket_exceptions += 1

Expand All @@ -78,11 +156,30 @@ def run(self):
print " total closed:", total_closed
print " no unique IPs:", len(unique_ips)
print "socket exceptions:", socket_exceptions
if genstats :
if fullconn_counts > 0:
print "overall average connection duration(s):", sum_durations/fullconn_counts
print "overall minimum connection duration(s):", min_connection_duration
print "overall maximum connection duration(s):", max_connection_duration
else:
print "overall average connection duration(s): -"
print "overall minimum connection duration(s): -"
print "overall maximum connection duration(s): -"
print

for ip in sorted(unique_ips, key=lambda x: ip_opened[x], reverse=True):
opened = ip_opened[ip] if ip in ip_opened else 0
closed = ip_closed[ip] if ip in ip_closed else 0

print "%-15s opened: %-8i closed: %-8i" % (ip, opened, closed)
if genstats:
covered_count = ipwise_count[ip] if ip in ipwise_count else 1
connection_duration_ip = ipwise_sum_durations[ip] if ip in ipwise_sum_durations else 0
ipwise_min_connection_duration_final = ipwise_min_connection_duration[ip] if ipwise_min_connection_duration[ip]!=MIN_DURATION_EMPTY else 0
ipwise_max_connection_duration_final = ipwise_max_connection_duration[ip] if ipwise_max_connection_duration[ip]!=MAX_DURATION_EMPTY else 0

print "%-15s opened: %-8i closed: %-8i dur-avg(s): %-8i dur-min(s): %-8i dur-max(s): %-8i" % (ip, opened, closed, connection_duration_ip/covered_count, ipwise_min_connection_duration_final, ipwise_max_connection_duration_final)
else:
print "%-15s opened: %-8i closed: %-8i" % (ip, opened, closed)

print

26 changes: 26 additions & 0 deletions mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_end_connid_notdigit.log
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,26 @@
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] MongoDB starting : pid=17340 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] db version v3.4.9
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] git version: 876ebee8c7dd0e2d992f36a848ff4dc50ee6603e
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] allocator: system
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] modules: none
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] build environment:
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] distarch: x86_64
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] target_arch: x86_64
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } }
2017-10-10T16:46:52.604+0530 I - [initandlisten] Detected data files in /Users/nishant/testcase/data created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2017-10-10T16:46:52.604+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten]
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database.
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted.
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten]
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten]
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000
2017-10-10T16:46:53.555+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data'
2017-10-10T16:46:53.556+0530 I NETWORK [thread1] waiting for connections on port 27017
2017-10-10T16:47:06.585+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63573 #1 (1 connection now open)
2017-10-10T16:47:08.582+0530 I - [conn1] end connection 127.0.0.1:63573 (1 connection now open)
2017-10-10T16:47:29.081+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63579 #2 (1 connection now open)
2017-10-10T16:47:30.991+0530 I - [conn2] end connection 127.0.0.1:63579 (1 connection now open)
2017-10-10T16:47:35.446+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63580 #3 (1 connection now open)
2017-10-10T16:48:08.656+0530 I - [conn3TEST] end connection 127.0.0.1:63580 (1 connection now open)
26 changes: 26 additions & 0 deletions mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_end_connid_repeated.log
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,26 @@
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] MongoDB starting : pid=17340 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] db version v3.4.9
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] git version: 876ebee8c7dd0e2d992f36a848ff4dc50ee6603e
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] allocator: system
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] modules: none
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] build environment:
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] distarch: x86_64
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] target_arch: x86_64
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } }
2017-10-10T16:46:52.604+0530 I - [initandlisten] Detected data files in /Users/nishant/testcase/data created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2017-10-10T16:46:52.604+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten]
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database.
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted.
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten]
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten]
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000
2017-10-10T16:46:53.555+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data'
2017-10-10T16:46:53.556+0530 I NETWORK [thread1] waiting for connections on port 27017
2017-10-10T16:47:06.585+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63573 #1 (1 connection now open)
2017-10-10T16:47:08.582+0530 I - [conn1] end connection 127.0.0.1:63573 (1 connection now open)
2017-10-10T16:47:29.081+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63579 #2 (1 connection now open)
2017-10-10T16:47:30.991+0530 I - [conn2] end connection 127.0.0.1:63579 (1 connection now open)
2017-10-10T16:47:35.446+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63580 #3 (1 connection now open)
2017-10-10T16:48:08.656+0530 I - [conn2] end connection 127.0.0.1:63580 (1 connection now open)
23 changes: 23 additions & 0 deletions mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_only_connection_accepted.log
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,23 @@
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] MongoDB starting : pid=17340 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] db version v3.4.9
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] git version: 876ebee8c7dd0e2d992f36a848ff4dc50ee6603e
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] allocator: system
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] modules: none
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] build environment:
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] distarch: x86_64
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] target_arch: x86_64
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } }
2017-10-10T16:46:52.604+0530 I - [initandlisten] Detected data files in /Users/nishant/testcase/data created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2017-10-10T16:46:52.604+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten]
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database.
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted.
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten]
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten]
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000
2017-10-10T16:46:53.555+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data'
2017-10-10T16:46:53.556+0530 I NETWORK [thread1] waiting for connections on port 27017
2017-10-10T16:47:06.585+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63573 #1 (1 connection now open)
2017-10-10T16:47:29.081+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63579 #2 (1 connection now open)
2017-10-10T16:47:35.446+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63580 #3 (1 connection now open)
23 changes: 23 additions & 0 deletions mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_only_connection_end.log
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,23 @@
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] MongoDB starting : pid=17340 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] db version v3.4.9
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] git version: 876ebee8c7dd0e2d992f36a848ff4dc50ee6603e
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] allocator: system
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] modules: none
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] build environment:
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] distarch: x86_64
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] target_arch: x86_64
2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } }
2017-10-10T16:46:52.604+0530 I - [initandlisten] Detected data files in /Users/nishant/testcase/data created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2017-10-10T16:46:52.604+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten]
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database.
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted.
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten]
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten]
2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000
2017-10-10T16:46:53.555+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data'
2017-10-10T16:46:53.556+0530 I NETWORK [thread1] waiting for connections on port 27017
2017-10-10T16:47:08.582+0530 I - [conn1] end connection 127.0.0.1:63573 (1 connection now open)
2017-10-10T16:47:30.991+0530 I - [conn2] end connection 127.0.0.1:63579 (1 connection now open)
2017-10-10T16:48:08.656+0530 I - [conn3] end connection 127.0.0.1:63580 (1 connection now open)
Loading

0 comments on commit 93d7080

Please sign in to comment.