Skip to content

Commit

Permalink
Fix #704: Display slow transactions in MongoDB 4.2+ (#719)
Browse files Browse the repository at this point in the history
- Added new flags for transaction in mloginfo and mlogfilter
  • Loading branch information
mitesh-gosavi authored and stennie committed Dec 20, 2019
1 parent 89ae6dc commit f67fc8a
Showing 8 changed files with 1,759 additions and 20 deletions.
47 changes: 46 additions & 1 deletion doc/mloginfo.rst
Original file line number Diff line number Diff line change
@@ -16,9 +16,9 @@ Usage
mloginfo [-h] [--version] logfile
[--verbose]
[--queries] [--restarts] [--distinct] [--connections] [--rsstate]
[--transactions] [--tsort {duration}]
[--cursor]
General Parameters
~~~~~~~~~~~~~~~~~~

@@ -141,6 +141,51 @@ example:
This option has no effect unless ``--queries`` is also specified.

Transactions (``--transactions``)
-----------------------

The transaction section will parse the log file to find information related
to transactions (MongoDB 4.0+). The autocommit indicates whether autocommit
was enabled for a transaction. The readConcern information is fetched either
from OperationContext or _txnResourceStash. TimeActiveMicros and TimeInactiveMicros
denote the number of micros active and inactive during the span of the transaction.
The duration field includes the value in milliseconds and indicates the amount
of time taken by each transaction.

For example:

.. code-block:: bash
mloginfo mongod.log --transactions
In addition to the default information, this command will also output the
``TRANSACTIONS`` section:

.. code-block:: bash
TRANSACTION
DATETIME TXNNUMBER AUTOCOMMIT READCONCERN TIMEACTIVEMICROS TIMEINACTIVEMICROS DURATION
2019-06-18T12:31:03.180+0100 1 false "snapshot" 11142 3 7
2019-03-18T12:31:03.180+0100 2 false "snapshot" 11143 4 6
2019-07-18T12:31:03.180+0100 3 false "snapshot" 11144 3 4
2019-08-18T12:31:03.180+0100 4 false "snapshot" 11145 4 7
2019-06-18T12:31:03.180+0100 5 false "snapshot" 11146 3 3
``--tsort``
^^^^^^^^^^

This option can be used to sort the results of the ``--transaction`` table, along with 'duration' keyword.

For example:

.. code-block:: bash
mloginfo mongod.log --transaction --tsort duration
This option has no effect unless it is specified between ``--transaction`` and ``duration`` is specified.

Restarts (``--restarts``)
-------------------------

1 change: 1 addition & 0 deletions mtools/mlogfilter/filters/__init__.py
Original file line number Diff line number Diff line change
@@ -5,3 +5,4 @@
from .tablescan_filter import TableScanFilter
from .word_filter import WordFilter
from .mask_filter import MaskFilter
from .transaction_filter import TransactionFilter
34 changes: 34 additions & 0 deletions mtools/mlogfilter/filters/transaction_filter.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,34 @@
import re

from .base_filter import BaseFilter

# SERVER-36461 - Filter to log slow transactions; Can be used in conjuncture with other filters


class TransactionFilter(BaseFilter):
filterArgs = [
('--transactions', {'action': 'store_true','default': False,
'help': 'only output lines containing logs of transactions'}),
]

def __init__(self, mlogfilter):
BaseFilter.__init__(self, mlogfilter)

# set the keyword as transaction if the --transaction flag is set
if self.mlogfilter.args['transactions']:
self.words = "transaction"
self.active = True
else:
self.active = False

def accept(self, logevent):
"""
Process line.
Overwrite BaseFilter.accept() and return True if the provided
logevent contains keyword transaction, or False if not.
"""

if re.search(self.words, logevent.line_str):
return True
else:
return False
3 changes: 2 additions & 1 deletion mtools/mloginfo/sections/__init__.py
Original file line number Diff line number Diff line change
@@ -5,4 +5,5 @@
from .rs_state_section import RsStateSection
from .rs_info_section import RsInfoSection
from .clients_section import ClientSection
from .cursor_section import CursorSection
from .cursor_section import CursorSection
from .transaction_section import TransactionSection
116 changes: 116 additions & 0 deletions mtools/mloginfo/sections/transaction_section.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,116 @@
# SERVER-36414 - Log information about slow transactions

import re
from collections import namedtuple
from operator import itemgetter
from mtools.util import OrderedDict
from mtools.util.grouping import Grouping
from mtools.util.print_table import print_table
from .base_section import BaseSection


LogTuple = namedtuple('LogTuple', ['datetime', 'txnNumber', 'autocommit', 'readConcern',
'timeActiveMicros', 'timeInactiveMicros', 'duration'])


def op_or_cmd(le):
return le.operation if le.operation != 'command' else le.command


class TransactionSection(BaseSection):
"""TransactionSection class."""

name = "transactions"

def __init__(self, mloginfo):
BaseSection.__init__(self, mloginfo)

# add --transactions flag to argparser
helptext = 'outputs statistics about transactions'
self.mloginfo.argparser_sectiongroup.add_argument('--transactions',
action='store_true',
help=helptext)

# add --tsort flag to argparser for transaction sort
self.mloginfo.argparser_sectiongroup.add_argument('--tsort',
action='store',

choices=['duration'])

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

def run(self):

"""Run this section and print out information."""
grouping = Grouping(group_by=lambda x: (x.datetime, x.txnNumber,
x.autocommit, x.readConcern, x.timeActiveMicros,
x.timeInactiveMicros, x.duration))

logfile = self.mloginfo.logfile

if logfile.start and logfile.end:
progress_start = self.mloginfo._datetime_to_epoch(logfile.start)
progress_total = (self.mloginfo._datetime_to_epoch(logfile.end) -
progress_start)
else:
self.mloginfo.progress_bar_enabled = False

for i, le in enumerate(logfile):
# update progress bar every 1000 lines

if self.mloginfo.progress_bar_enabled and (i % 1000 == 0):
if le.datetime:
progress_curr = self.mloginfo._datetime_to_epoch(le.datetime)
if progress_total:
(self.mloginfo
.update_progress(float(progress_curr -
progress_start) /
progress_total))

if re.search('transaction', le.line_str):
lt = LogTuple(le.datetime, le.txnNumber, le.autocommit, le.readConcern,
le.timeActiveMicros, le.timeInactiveMicros, le.duration)

grouping.add(lt)

grouping.sort_by_size()

# clear progress bar again
if self.mloginfo.progress_bar_enabled:
self.mloginfo.update_progress(1.0)

# no queries in the log file
if not len(grouping):
print('no transactions found.')
return

titles = ['datetime','txnNumber', 'autocommit', 'readConcern', 'timeActiveMicros',
'timeInactiveMicros', 'duration']

table_rows = []
# using only important key-values
# can be used in future
for g in grouping:
# calculate statistics for this group
datetime, txnNumber, autocommit, readConcern, timeActiveMicros, timeInactiveMicros, duration = g
stats = OrderedDict()
stats['datetime'] = str(datetime)
stats['txnNumber'] = txnNumber
stats['autocommit'] = autocommit
stats['readConcern'] = readConcern
stats['timeActiveMicros'] = timeActiveMicros
stats['timeInactiveMicros'] = timeInactiveMicros
stats['duration'] = duration
table_rows.append(stats)

if self.mloginfo.args['tsort'] == 'duration':
table_rows = sorted(table_rows,
key=itemgetter(self.mloginfo.args['tsort']),
reverse=True)

print_table(table_rows, titles, uppercase_headers=True)

print('')
Loading

0 comments on commit f67fc8a

Please sign in to comment.