Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix #518: Add mloginfo --connstats for connection duration metrics #530

Merged
merged 6 commits into from
Oct 11, 2017
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
103 changes: 100 additions & 3 deletions mtools/mloginfo/sections/connection_section.py
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(':')
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[Optional] Not directly related to this change, but we need to consider a case where there is no element entry in the array. Attempting to access an index of array out of bound will produce IndexError exception, which should be handled

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

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)
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)
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)
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