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

hasaketa · 2017-10-10T07:05:25Z

Description of changes

Added option --stats to --connections option. It outputs helpful statistics for connection duration (min/max/avg).

Testing

Usual nosetests, test against different log files.

O/S testing:

O/S	Version(s)
Linux	TBD
macOS	10.12.6
Windows	NA

…inal

stennie

Aside from general suggestions from review, please add test coverage in mtools/test/test_mloginfo.py

stennie · 2017-10-10T07:08:20Z

mtools/mloginfo/sections/connection_section.py

@@ -19,6 +20,7 @@ def __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('--stats', action='store_true', help='outputs helpful statistics for connection duration (min/max/avg)')


I think you can make this more intuitive to use:
---stats is too generic given this option is specific to connections.

The --stats option doesn't do anything unless you also specify --connections.

Suggest you make a top level connection-stats section so the command line usage would be mloginfo --connection-stats ....

done now mloginfo --connection --connstats logfile and mloginfo --connstats logfile have same meaning

stennie · 2017-10-10T07:14:14Z

mtools/mloginfo/sections/connection_section.py

@@ -19,6 +20,7 @@ def __init__(self, mloginfo):

        # add --restarts flag to argparser


Not directly related to this change, but the comment is incorrect so you could fix if you are adding extra args

stennie · 2017-10-10T07:18:25Z

mtools/test/logfiles/mongod_3_4_2.log

@@ -0,0 +1,27 @@
+2017-10-09T12:44:35.031+0530 I CONTROL  [initandlisten] MongoDB starting : pid=10686 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local


Since this log is intended for testing the connection feature, the naming should reflect that. Maybe mongod_3_4-2_connection-stats.log?

For completeness can you generate and include test logs for 3.0 and 3.2? I would also suggest latest 3.4.x rather than 3.4.2.

stennie · 2017-10-10T07:26:23Z

mtools/mloginfo/sections/connection_section.py

@@ -1,5 +1,6 @@
 from base_section import BaseSection
 from collections import defaultdict
+from datetime import datetime, date, time


This import doesn't appear to be needed. Not calling any date functions in the current PR?

stennie · 2017-10-10T07:26:53Z

mtools/mloginfo/sections/connection_section.py

        socket_exceptions = 0

+        genstats = self.mloginfo.args['stats']
+        if genstats:
+            genstats = True


Not needed (genstats is already True per the previous line)

I was earlier using self.mloginfo.args['stats'] directly in comparison, now genstats = True is redundant. Removed.

stennie · 2017-10-10T07:29:38Z

mtools/mloginfo/sections/connection_section.py

+                    ipwise_min_connection_duration[ip]
+                    ipwise_max_connection_duration[ip]
+
+                    connid = tokens[4].strip('#')


Should perhaps move this into an else clause for the date comparison to avoid doing unnecessary work

I would also consider moving the parsing of connection ID to logevent since this could be useful elsewhere.

Agreed parsing of connection ID should be in logevent. The other code now removed as redundant with new changes.

stennie · 2017-10-10T07:31:04Z

mtools/mloginfo/sections/connection_section.py

+                    connid = tokens[4].strip('#')
+
+                    if dt != None:                  
+                        connections_start[connid] = dt           


Should this be checking if there is already a start datetime for the given connection ID?

If there are multiple start datetimes found for the same connection ID should that raise an exception?

Done will raise and exception now.

will also raise exception if duplicate end connection ids

I'm trying to understand why we need to raise an exception for this? I just encountered this exception on some 3.4.23 logs. Couldn't this just be a datetime precision issue?

Ah, can this be raised when the same connection ID is reused during the same log period? The logs I have are for 24 hours but has a very high connection churn, so it's not impossible that this will happen on perfectly OK log files.

Btw, filtering to a 1 hour period worked around the exception. Maybe the exception message should state the connection number that repeats?

stennie · 2017-10-10T07:35:09Z

mtools/mloginfo/sections/connection_section.py

        print
+
+        if genstats and fullconn_counts > 0:
+            print "Average connection duration across all IPs %d seconds, Minimum duration %d , Maximum duration %d" % (sum_durations/fullconn_counts, min_connection_duration, max_connection_duration)


To match the output style of other mloginfo sections, I would lowercase Minimum and Maximum.

I think the order of output here should also match the info above (avg/min/max) and be in a similar format for consistency.

stennie · 2017-10-10T07:38:07Z

mtools/mloginfo/sections/connection_section.py

+                    tokens_conn = line[:pos].split(' ')
+                    end_connid = tokens_conn[3].strip('[|conn|]')
+
+                    #Check if we have the starting of this connid


Think this needs some check of the validity of end_connid before trying to use as a dict key

stennie · 2017-10-10T07:39:38Z

mtools/mloginfo/sections/connection_section.py

+
+                    #Check if we have the starting of this connid
+                    if connections_start[end_connid]:
+                        if dt != None:


This could be included in the if statement above

sindbach

Thanks for working on this issue to improve connections section. Most of changes here just need some tweaks. Good work.

sindbach · 2017-10-10T08:04:15Z

mtools/mloginfo/sections/connection_section.py

+            ipwise_min_connection_duration = defaultdict(lambda:9999999999)
+            ipwise_max_connection_duration = defaultdict(lambda:-1)
+
+            min_connection_duration = 9999999999


You could declare min_connection_duration and max_connection_duration before ipwise_min and ipwise_max declaration to avoid repeating the same values. i.e. lambda: min_connection_duration

[Optional] replace defaultdict with normal dict to be explicit in your dictionary key declaration.

sindbach · 2017-10-10T08:08:50Z

mtools/mloginfo/sections/connection_section.py

@@ -51,6 +71,18 @@ def run(self):
                    ip, _ = tokens[3].split(':')


[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

sindbach · 2017-10-10T08:32:48Z

mtools/mloginfo/sections/connection_section.py

+                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
+
+                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[ip], ipwise_max_connection_duration[ip])


Would you be able to print them out a stat per line to be consistent with the other outputs of the module. See line 141.

this is as per existing format, the stats are printed against their respective ip

I got your point added overall stats to stat per line format

…ing improvements: - Replace magic numbers with symbolic Constants - Fixed a bug where magic numbers were returned if the related ip does not cover all the ips - Raise NotImplemented Error if Multiple start/end datetimes were found for the same connection ID - Check for connection id is a digit - Add more performant/robust re pattern search on connid - Add nosetests for --connstats - Added folder connstats to mtools/test/logfiles with more logfiles specific to connstats testing ToDO: - Write nosetests for connstats using logfiles in mtools/test/logfiles/connstats folder

- Add logfiles specific to connstats

Looks like initial feedback has been addressed aside from adding nosetests.

- Fixed bug that raises an exception when connection id in end connection string is not a digit. - Now shows a dash(-) when no complete connections are found - Add nosetests for --connstats

hasaketa · 2017-10-11T05:04:04Z

Added nosetests and minor fixes.

Nishant Bhardwaj added 3 commits October 9, 2017 17:34

Fix 518: Add min/max/avg connection durations

d3bf6b0

Added option --stats to show min/max/avg connection durations

c89df5a

Fix 518: Removed debug print commands and added import re as per orig…

e67043e

…inal

stennie added this to the 1.3.2 milestone Oct 10, 2017

stennie requested a review from sindbach October 10, 2017 07:06

stennie previously requested changes Oct 10, 2017

View reviewed changes

sindbach reviewed Oct 10, 2017

View reviewed changes

stennie changed the title ~~Issue 518~~ Fix #518: Add mloginfo --connections support for connection duration metrics Oct 10, 2017

stennie added mloginfo improvement labels Oct 10, 2017

Nishant Bhardwaj added 2 commits October 10, 2017 18:08

Fix-518:

3e6e14c

- Add logfiles specific to connstats

Fix:518:

6410659

- Fixed bug that raises an exception when connection id in end connection string is not a digit. - Now shows a dash(-) when no complete connections are found - Add nosetests for --connstats

sindbach merged commit 93d7080 into rueckstiess:develop Oct 11, 2017

stennie changed the title ~~Fix #518: Add mloginfo --connections support for connection duration metrics~~ Fix #518: Add mloginfo --connstats for connection duration metrics Oct 23, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

hasaketa commented Oct 10, 2017

stennie left a comment

stennie Oct 10, 2017

hasaketa Oct 10, 2017

stennie Oct 10, 2017

hasaketa Oct 10, 2017

stennie Oct 10, 2017

stennie Oct 10, 2017

stennie Oct 10, 2017

hasaketa Oct 10, 2017

stennie Oct 10, 2017

hasaketa Oct 10, 2017

stennie Oct 10, 2017

stennie Oct 10, 2017

hasaketa Oct 10, 2017

stennie Oct 10, 2017

hasaketa Oct 10, 2017

hasaketa Oct 10, 2017

niccottrell Dec 17, 2019

niccottrell Dec 17, 2019

niccottrell Dec 17, 2019

stennie Oct 10, 2017

hasaketa Oct 10, 2017

stennie Oct 10, 2017

hasaketa Oct 10, 2017

stennie Oct 10, 2017

hasaketa Oct 10, 2017

sindbach left a comment

sindbach Oct 10, 2017

sindbach Oct 10, 2017

sindbach Oct 10, 2017

hasaketa Oct 10, 2017

hasaketa Oct 10, 2017

hasaketa commented Oct 11, 2017

		@@ -19,6 +20,7 @@ def __init__(self, mloginfo):

		# add --restarts flag to argparser

		@@ -0,0 +1,27 @@
		2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] MongoDB starting : pid=10686 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local

		@@ -51,6 +71,18 @@ def run(self):
		ip, _ = tokens[3].split(':')

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

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

Conversation

hasaketa commented Oct 10, 2017

Description of changes

Testing

stennie left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sindbach left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hasaketa commented Oct 11, 2017