Stethoscope

Stethoscope mk Tue, 03/30/2010 - 12:20

The program stethoscope is a simple Linux application that can attach itself to a running MonetDB server and extracts the profiler events from concurrent running queries. Stethoscope is an online-only inspection tool, i.e., it only monitors the execution state of the current queries and outputs the information in STDOUT for immediate inspection. For example, the following command tracks the microsecond ticks for all database instructions denoted in MAL on a database called “voc”:

    $ stethoscope -u monetdb -P monetdb -d voc

A synopsis of the calling conventions:

    stethoscope [options]
      -d | --dbname=<database_name>
      -u | --user=<user>
      -P | --password=<password>
      -p | --port=<portnr>
      -h | --host=<hostname>
      -o | --output=<local file name>
      -b | --beat=<delay> in milliseconds (default 50)

Before stethoscope  starts parsing command line options, it first tries to read configuration information from a “.monetdb” file.  If the environment variable DOTMONETDBFILE is set, it reads the file pointed to by that variable instead. When unset, stethoscope searches for a “.monetdb” file in the current working directory, and if that does not exist, in the current user‘s home directory. This file can contain defaults for command line keys, e.g., user, password, language, save_history, format and width.

The output produced by stethoscope consists of heartbeat events and MAL instruction traces. The heartbeat is issued at regular intervals and contains as main piece of information the recent CPU load of all cores as made available by the (Linux) operating system. The text below shows an excerpt of the stethoscope output for the query “SELECT id FROM _tables;”:

$ stethoscope -d voc -b 50000
-- opened UDP profile stream numa-db:50010 for localhost
# event,        time,   pc,     thread, state,  usec,   rssMB,  tmpspace,       inblock,        oublock,        majflt, nswap,  switch, stmt,   # name
...
[ 6,    "13:11:15.060773",      "user.ping[0]0",        4,      "ping", 0,      58,     0,      0,      0,      0,      0,      1,      "[  0.00  0.00  0.00  0.00  0.01  0.01  0.01  0.00  1.00  1.00  0.01  0.01  0.01  1.00  1.00  1.00  1.00  0.01  1.00  0.01  0.00  0.07  0.00  0.00  0.01  0.01  0.00  0.01  0.00  0.00  0.05  0.02  0.00  0.00  0.00  0.04  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.00  0.00  0.00  0.01 ]",  ]
...
[ 8,    "13:11:16.703220",      "user.s5_1[0]12",       3,      "start",        0,      54,     0,      0,      0,      0,      0,      484,     "function user.s5_1{autoCommit=true}():void;",       ]
...
[ 10,   "13:11:16.704600",      "user.s5_1[1]12",       3,      "start",        0,      54,     0,      0,      0,      0,      0,      0,       "X_23=0@0:void := querylog.define(\"select id from _tables;\":str,\"default_pipe\":str,16:int);",    ]
[ 11,   "13:11:16.704742",      "user.s5_1[1]12",       3,      "done ",        140,    54,     0,      0,      0,      0,      0,      0,       "X_23=0@0:void := querylog.define(\"select id from _tables;\":str,\"default_pipe\":str,16:int);",    ]
[ 12,   "13:11:16.704881",      "user.s5_1[2]12",       3,      "start",        0,      54,     0,      0,      0,      0,      0,      0,       "barrier X_37=false:bit{transparent} := language.dataflow();",       ]
[ 13,   "13:11:16.705111",      "user.s5_1[3]12",       28,     "start",        0,      54,     0,      0,      0,      0,      0,      2,       "X_2=0:int := sql.mvc();",     ]
[ 14,   "13:11:16.705305",      "user.s5_1[3]12",       28,     "done ",        193,    54,     0,      0,      0,      0,      0,      0,       "X_2=0:int := sql.mvc();",     ]
[ 15,   "13:11:16.705419",      "user.s5_1[4]12",       28,     "start",        0,      54,     0,      0,      0,      0,      0,      0,       "X_3=nil:bat[:oid,:oid] := sql.tid(X_2=0:int,\"sys\":str,\"_tables\":str);", ]
[ 16,   "13:11:16.705468",      "user.s5_1[5]12",       6,      "start",        0,      54,     0,      0,      0,      0,      0,      0,       "X_6=nil:bat[:oid,:int]{file=\"/home/demouser27/tst/./bat/07/736\", rows=45, hlb>=0@0:oid, hub<45@0:oid} := sql.bind(X_2=0:int,\"sys\":str,\"_tables\":str,\"id\":str,0:int);",      ]
[ 17,   "13:11:16.705459",      "user.s5_1[7]12",       22,     "start",        0,      54,     0,      0,      0,      0,      0,      0,       "X_12=nil:bat[:oid,:int]{file=\"/home/demouser27/tst/./bat/07/736\", hlb>=45@0:oid, hub<1048621@0:oid} := sql.bind(X_2=0:int,\"sys\":str,\"_tables\":str,\"id\":str,1:int);",        ]
[ 18,   "13:11:16.705719",      "user.s5_1[5]12",       6,      "done ",        250,    54,     0,      0,      0,      0,      0,      1,       "X_6=[45]:bat[:oid,:int]{file=\"/home/demouser27/tst/./bat/07/736\", rows=45, hlb>=0@0:oid, hub<45@0:oid} := sql.bind(X_2=0:int,\"sys\":str,\"_tables\":str,\"id\":str,0:int);",    ]
[ 19,   "13:11:16.705799",      "user.s5_1[7]12",       22,     "done ",        339,    54,     0,      0,      0,      0,      0,      2,       "X_12=[0]:bat[:oid,:int]{file=\"/home/demouser27/tst/./bat/07/736\", hlb>=45@0:oid, hub<1048621@0:oid} := sql.bind(X_2=0:int,\"sys\":str,\"_tables\":str,\"id\":str,1:int);",      ]
[ 20,   "13:11:16.706113",      "user.s5_1[4]12",       28,     "done ",        693,    54,     0,      0,      0,      0,      0,      5,       "X_3=[43]:bat[:oid,:oid] := sql.tid(X_2=0:int,\"sys\":str,\"_tables\":str);",      ]
[ 21,   "13:11:16.705459",      "user.s5_1[6]12",       12,     "start",        0,      54,     0,      0,      0,      0,      0,      1,       "(X_9=nil:bat[:oid,:oid]{file=\"/home/demouser27/tst/./bat/07/736\", rows=45, hlb>=0@0:oid, hub<45@0:oid},r1_9=nil:bat[:oid,:int]) := sql.bind(X_2=0:int,\"sys\":str,\"_tables\":str,\"id\":str,2:int);",    ]
[ 22,   "13:11:16.706800",      "user.s5_1[6]12",       12,     "done ",        1339,   54,     0,      0,      0,      0,      0,      2,       "(X_9=[0]:bat[:oid,:oid]{file=\"/home/demouser27/tst/./bat/07/736\", rows=45, hlb>=0@0:oid, hub<45@0:oid},r1_9=[0]:bat[:oid,:int]) := sql.bind(X_2=0:int,\"sys\":str,\"_tables\":str,\"id\":str,2:int);",      ]
[ 23,   "13:11:16.706948",      "user.wait[0]0",        6,      "wait", 0,      54,     0,      0,      0,      0,      0,      3,      "[  0.01  0.00  0.00  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.00  0.01  0.00  0.00  0.01  0.01  0.01  0.00  0.01  0.00  0.00  0.01  0.01  0.00  0.00  0.00  0.00  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01  0.01 ]",      ]
...
[ 25,   "13:11:16.708063",      "user.s5_1[8]12",       45,     "start",        0,      54,     0,      0,      0,      0,      0,      0,       "X_14=nil:bat[:oid,:int] := sql.delta(X_6=[45]:bat[:oid,:int],X_9=[0]:bat[:oid,:oid],r1_9=[0]:bat[:oid,:int],X_12=[0]:bat[:oid,:int]);",      ]
[ 26,   "13:11:16.708329",      "user.s5_1[8]12",       45,     "done ",        265,    54,     0,      0,      0,      0,      0,      1,       "X_14=[45]:bat[:oid,:int] := sql.delta(X_6=[45]:bat[:oid,:int],X_9=[0]:bat[:oid,:oid],r1_9=[0]:bat[:oid,:int],X_12=[0]:bat[:oid,:int]);",    ]
[ 27,   "13:11:16.708445",      "user.s5_1[9]12",       45,     "start",        0,      54,     0,      0,      0,      0,      0,      0,       "X_15=nil:bat[:oid,:int] := algebra.leftfetchjoin(X_3=[43]:bat[:oid,:oid],X_14=[45]:bat[:oid,:int]);",    ]
[ 28,   "13:11:16.708561",      "user.s5_1[9]12",       45,     "done ",        116,    54,     0,      0,      0,      0,      0,      1,       "X_15=[43]:bat[:oid,:int] := algebra.leftfetchjoin(X_3=[43]:bat[:oid,:oid],X_14=[45]:bat[:oid,:int]);",  ]
...
[ 30,   "13:11:16.708994",      "user.s5_1[2]12",       3,      "done ",        4112,   54,     0,      0,      0,      0,      0,      3,       "barrier X_37=false:bit{transparent} := language.dataflow();",       ]
[ 31,   "13:11:16.709419",      "user.s5_1[11]12",      3,      "start",        0,      54,     0,      0,      0,      0,      0,      2,       "X_16=0:int := sql.resultSet(1:int,1:int,X_15=[43]:bat[:oid,:int]);",       ]
[ 32,   "13:11:16.709529",      "user.s5_1[11]12",      3,      "done ",        109,    54,     0,      0,      0,      0,      0,      0,       "X_16=4:int := sql.resultSet(1:int,1:int,X_15=[43]:bat[:oid,:int]);",       ]
[ 33,   "13:11:16.709617",      "user.s5_1[12]12",      3,      "start",        0,      54,     0,      0,      0,      0,      0,      0,       "sql.rsColumn(X_16=4:int,\"sys._tables\":str,\"id\":str,\"int\":str,32:int,0:int,X_15=[43]:bat[:oid,:int]);",       ]
[ 34,   "13:11:16.709717",      "user.s5_1[12]12",      3,      "done ",        100,    54,     0,      0,      0,      0,      0,      0,       "sql.rsColumn(X_16=4:int,\"sys._tables\":str,\"id\":str,\"int\":str,32:int,0:int,X_15=[43]:bat[:oid,:int]);",       ]
[ 35,   "13:11:16.709816",      "user.s5_1[13]12",      3,      "start",        0,      54,     0,      0,      0,      0,      0,      0,       "X_21=nil:streams := io.stdout();", ]
[ 36,   "13:11:16.709896",      "user.s5_1[13]12",      3,      "done ",        79,     54,     0,      0,      0,      0,      0,      0,       "X_21=\"104d2\":streams := io.stdout();",    ]
[ 37,   "13:11:16.709973",      "user.s5_1[14]12",      3,      "start",        0,      54,     0,      0,      0,      0,      0,      0,       "sql.exportResult(X_21=\"104d2\":streams,X_16=4:int);",      ]
[ 38,   "13:11:16.710180",      "user.s5_1[14]12",      3,      "done ",        207,    54,     0,      0,      0,      0,      0,      0,       "sql.exportResult(X_21=\"104d2\":streams,X_16=4:int);",      ]
[ 39,   "13:11:16.710264",      "user.s5_1[15]12",      3,      "start",        0,      54,     0,      0,      0,      0,      0,      0,       "end user.s5_1;",      ]
[ 40,   "13:11:16.710325",      "user.s5_1[15]12",      3,      "done ",        61,     54,     0,      0,      0,      0,      0,      0,       "end user.s5_1;",      ]
...
[ 43,   "13:11:16.711494",      "user.s5_1[0]12",       3,      "done ",        8273,   54,     0,      0,      0,      0,      0,      0,       "function user.s5_1{autoCommit=true}():void;",       ]
...
^Csignal 2 received