ToC path:

xSQL Statistics Logging

When running as server, xSQL collects information to allow examination of the state of the server without the need to attach a debugger to the server process. Also basic connection lock information is provided to examine the states of the client connections.

For an overview see page xSQL Server Instrumentation

Statistics Logging

For each statement executed by xSQL the following information is logged:

The IP-Address and port of the connected client

The current state of the client: connected or disconnected

The wall-time when the execution of the statement was started on the server

The current state of the statement:
ACTIVE - the statement is active
DONE - the statement has been successfully completed
FAILED - the statement has completed with an error
CANCELED - the statement has been interrupted , this is often due to some network problems (unable send or receive data)

The SQL statement itself

The array of the query parameters

The error message, (if the statement FAILED or was CANCELED)

The maximum memory consumption during the statement execution (in bytes)

The size of the result set: the number of rows that the select created or the insert/update/delete modified

The size of the result set in bytes — the size of the set transmitted over the network from the server to the client. (This makes sense only for select statements.)

The overall statement execution time in microseconds (from the time the statement was received until the server finished sending the result set back to the client)

The overall statement result set transmission time in microseconds. (Consequently this value minus the overall statement execution time (10) represents the time the statement required to execute on the server locally.)

Various statistics received from getrusage :
CPU user time - the CPU time spent by the process running the statement in the user space
CPU kernel time – the CPU time spent by the process running the statement in the kernel space
in bytes - the number of bytes read from persistent media (does not include cache reads)
out bytes - the number of bytes written to persistent media
nswaps - the total swap size during the statement execution
ncsw - the number of context switches during the statement execution

The xSQL configuration parameters for logging parameters are defined in the xlog_params section. The runtime statistics for all SQL statements executed by a client are accumulated by the server process in the pseudo-table xsql_stat (actually a circular log buffer).

To demonstrate logging, start xSQL as server from directory samples\xsql\scripts in one console window with the following command:
 
    ..\..\..\target\bin\xsql.exe -size 100m -p 5000 -c xsql.cfg
    press Enter to stop SQL server
 
Then run xSQL as client from directory samples\xsql\scripts in a separate console window and execute the script file index.sql as follows:
 
    ..\..\..\target\bin\xsql.exe @127.0.0.1:5000
    xsql started
    Runtime configuration
     Remote node(s)       : 127.0.0.1:5500
     Runtime              : Release
    XSQL>script index.sql
    autoid  sid     sname   status  dat     city    keywords
    ------------------------------------------------------------------------------
    22      S4      Clark   20      12/31/1969 16:00:00     London  []
    21      S3      Black   30      12/31/1969 16:00:00     Paris   []
    20      S2      Jones   10      12/31/1969 16:00:00     Paris   []
    19      S1      Smith   20      12/31/1969 16:00:00     London  []
    23      S5      Adams   30      12/31/1969 16:00:00     Athens  []
     
    Selected records: 5
 
Now the runtime statistics can be accessed with the xlog command:
     
    XSQL>xlog
    Node 127.0.0.1 :
     
    Timestamp                State  UsedMem      nRows  nBytes  ExecTime  TxTime     CPUUsage          I/O        SQL
    Client 127.0.0.1:6335 (ID 181407441810562, connected) :
    2017-01-18 15:39:38 :   DONE       4962          1       55      0us     0us     0us+0us           0/0        1:insert into S (sid,sname,status,city) values('S1', 'Smith', 20, 'London')
    2017-01-18 15:39:38 :   DONE       4960          1       55      0us     0us     0us+0us           0/0        2:insert into S (sid,sname,status,city) values('S2', 'Jones', 10, 'Paris')
    2017-01-18 15:39:38 :   DONE       4960          1       55      0us     0us     0us+0us           0/0        3:insert into S (sid,sname,status,city) values('S3', 'Black', 30, 'Paris')
    2017-01-18 15:39:38 :   DONE       4962          1       55   1003us     0us     0us+0us           0/0        4:insert into S (sid,sname,status,city) values('S4', 'Clark', 20, 'London')
    2017-01-18 15:39:38 :   DONE       4962          1       55      0us     0us     0us+0us           0/0        5:insert into S (sid,sname,status,city) values('S5', 'Adams', 30, 'Athens')
    2017-01-18 15:39:38 :   DONE        70K          5      520      0us     0us     0us+0us           0/0        6:select * from S
    2017-01-18 15:39:38 :   DONE       5311          5       55      0us     0us     0us+0us           0/0        7:delete from S
     
Alternatively by querying the pseudo-table xsql_stat directly:
 
    XSQL>select clientid, sql from xsql_stat;
    clientid        sql
    ------------------------------------------------------------------------------
    181408391970457 insert into S (sid,sname,status,city) values('S1', 'Smith', 20, 'London')
    181408391970457 insert into S (sid,sname,status,city) values('S2', 'Jones', 10, 'Paris')
    181408391970457 insert into S (sid,sname,status,city) values('S3', 'Black', 30, 'Paris')
    181408391970457 insert into S (sid,sname,status,city) values('S4', 'Clark', 20, 'London')
    181408391970457 insert into S (sid,sname,status,city) values('S5', 'Adams', 30, 'Athens')
    181408391970457 select * from S
    181408391970457 delete from S
    181408391970457 select clientid, sql from xsql_stat
     
    Selected records: 8
     
Or by calling function xsql_stat():
 
    XSQL>select xsql_stat(true,true);
    #1
    ------------------------------------------------------------------------------
    [{181408391970457, 1, 1, 13129257332933040, 127.0.0.1, 6580, DONE, 
    insert into S (sid,sname,status,city) values('S1', 'Smith', 20, 'London'), , 4962, 1, 55, 0, 0, 0, 0, 0, 0, 0, 0, 0}, 
    {181408391970457, 2, 1, 13129257332933040, 127.0.0.1, 6580, DONE, 
    insert into S (sid,sname,status,city) values('S2', 'Jones', 10, 'Paris'), , 4960, 1, 55, 0, 0, 0, 0, 0, 0, 0, 0, 0}, 
    {181408391970457, 3, 1, 13129257332933040, 127.0.0.1, 6580, DONE, 
    insert into S (sid,sname,status,city) values('S3', 'Black', 30, 'Paris'), , 4960, 1, 55, 1002, 1002, 0, 0, 0, 0, 0, 0, 0}, 
    {181408391970457, 4, 1, 13129257332934042, 127.0.0.1, 6580, DONE, 
    insert into S (sid,sname,status,city) values('S4', 'Clark', 20, 'London'), , 4962, 1, 55, 0, 0, 0, 0, 0, 0, 0, 0, 0}, 
    {181408391970457, 5, 1, 13129257332934042, 127.0.0.1, 6580, DONE, 
    insert into S (sid,sname,status,city) values('S5', 'Adams', 30, 'Athens'), , 4962, 1, 55, 0, 0, 0, 0, 0, 0, 0, 0, 0}, 
    {181408391970457, 6, 1, 13129257332934042, 127.0.0.1, 6580, DONE, 
    select * from S, , 72009, 5, 520, 0, 0, 0, 0, 0, 0, 0, 0, 0}, 
    {181408391970457, 7, 1, 13129257332938762, 127.0.0.1, 6580, DONE, 
    delete from S, , 5311, 5, 55, 0, 0, 0, 0, 0, 0, 0, 0, 0}, 
    {181408391970457, 8, 1, 13129257362524705, 127.0.0.1, 6580, DONE, 
    select clientid, sql from xsql_stat, , 78243, 8, 652, 0, 0, 0, 0, 0, 0, 0, 0, 0}, 
    {181408391970457, 9, 1, 13129257513099572, 127.0.0.1, 6580, ACTIVE, 
    select xsql_stat(true,true), , 71198, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}]
     
    Selected records: 1
 
Pseudo-table xsql_stat

The xsql_stat table structure can be represented as follows (each row corresponds to a single SQL statement execution):
 
    create table xsql_stat (
        clientid int,     -- client ID
        statementid int,  -- query ID
        connected, int,   -- client status: 1 - connected, 0 - disconnected
        begin int,        -- the time the query has been initiated
        ip string,        -- client IP
        port int,         -- client port
        state string,     -- "ACTIVE", "DONE", "FAILED" or "CANCELED"
        sql string,       -- SQL query
        failmsg string,   -- error message
        -- Query statistics and getrusage :
        memory int,
        rows int,
        bytes int,
        exectime int,
        txtime int,
        res_ucpu int,
        res_scpu int,
        res_inb int,
        res_outb int,
        res_maxrss int,
        res_nswap int,
        res_ncsw int
    );
     
Function xsql_stat()

Function xsql_stat() has two boolean parameters show_disconnected_clients, and show_statistics_queries that determine whether to display statistics for clients that have been disconnected and whether to display statistics for queries against the xsql_stat table.

The function returns information in the form of an array of structures with the set of fields defined above. (Note that when called via the Remote SQL engine, the entire result is returned in a single very long packet and all of these fields must fit into the communication buffer whose size is defined by the configuration file sql_comm_buffer parameter. If many logs are collected, it is quite possible to receive the “buffer too small” error. If instead of calling function xsql_stat() the xsql_stat table is queried, there is no limit to the number of log records to receive.)

Function xsql_show_log(int)

The function xsql_show_log() can be called from a remote client to display the last lines from the server's log. It has a single argument int n_lines that determines the number of lines of output to retrieve from the server. For examples
 
    XSQL>select xsql_show_log(10);
    #1
    ------------------------------------------------------------------------------
    2017-02-05 18:31:44.298748 : xsql started
    2017-02-05 18:31:44.298814 : Runtime configuration
    2017-02-05 18:31:44.298819 :   Transaction manager  : MURSIW
    2017-02-05 18:31:44.298825 :   Storage (transient)  : Conventional memory, 100M
    2017-02-05 18:31:44.298829 :   Storage (persistent) : Not supported
    2017-02-05 18:31:44.298833 :   Runtime              : Debug
 
    Selected records: 1
     
Command xlog

The command xlog implements the query “select * from xsql_stat ...' and (by default) groups the results first by shard and then by clientID. For example, if there are two shards, the following statistics might be displayed:
 
    XSQL>xlog
    Node 127.0.0.1:5000 (shard 1) :
    Timestamp               State  UsedMem   nRows  nBytes ExecTime  TxTime CPUUsage I/O        SQL
    Client 127.0.0.1:38800 (ID 48885306639241, connected) :
    2016-02-23 23:43:34 :   DONE       6706   4096   55    23ms    47us    23ms+0us  0/0        15:insert into a select 1 from a
    2016-02-23 23:43:34 :   DONE       6706    8192  55    39ms    57us    39ms+0us  0/0        16:insert into a select 1 from a
    2016-02-23 23:43:35 :   DONE       6706   16384  55    66ms    22us    65ms+0us  0/0        17:insert into a select 1 from a
    2016-02-23 23:43:35 :   DONE       6706   32768  55   122ms    58us   122ms+0us  0/0        18:insert into a select 1 from a
    2016-02-23 23:43:35 :   DONE       6706   65536  55   251ms    77us   252ms+0us  0/0        19:insert into a select 1 from a
    2016-02-23 23:43:36 :   DONE       6706  131072  55   532ms    77us   532ms+0us  0/0        20:insert into a select 1 from a
    2016-02-23 23:43:41 :   DONE       6706  262144  55  1085ms    76us  1085ms+0us  0/0        21:insert into a select 1 from a
    2016-02-23 23:43:57 :   DONE        69K  524288 5632K 3541ms 3391ms 145ms+2000us 0/0        22:select * from a
     
    Node 127.0.0.1:5001 (shard 2) :
    Timestamp                State  UsedMem   nRows  nBytes ExecTime TxTime CPUUsage  I/O        SQL
    Client 127.0.0.1:57335 (ID 48885306639241, connected) :
    2016-02-23 23:43:34 :   DONE       6706    4096  55   21ms    58us    21ms+0us    0/0        15:insert into a select 1 from a
    2016-02-23 23:43:34 :   DONE       6706    8192  55   42ms    24us    42ms+0us    0/0        16:insert into a select 1 from a
    2016-02-23 23:43:35 :   DONE       6706   16384  55   62ms    34us    63ms+0us    0/0        17:insert into a select 1 from a
    2016-02-23 23:43:35 :   DONE       6706   32768  55  124ms    36us   124ms+0us    0/0        18:insert into a select 1 from a
    2016-02-23 23:43:35 :   DONE       6706   65536  55  254ms    54us   255ms+0us    0/0        19:insert into a select 1 from a
    2016-02-23 23:43:36 :   DONE       6706  131072  55  525ms    68us   526ms+0us    0/0        20:insert into a select 1 from a
    2016-02-23 23:43:41 :   DONE       6706  262144  55  1090ms    67us  1091ms+0us   0/0        21:insert into a select 1 from a
    2016-02-23 23:43:57 :   DONE        69K  524288  5632K 3567ms 3416ms 149ms+3000us 0/0        22:select * from a
     
Alternatively, the parameter byquery can be specified to group the results first by clientID and then by queryID for each shard. This makes it is easier to see the execution statistics of the query on different shards. For example:
 
    XSQL>xlog byquery
    Client 127.0.0.1:38800 (ID 48885306639241, connected) :
    Node  Timestamp            State UsedMem nRows nBytes ExecTime TxTime CPUUsage  I/O        ErrorMsg
    Query [22] select * from a :
     01:01 2016-02-23 23:43:57 : DONE  69K    524288 5632K 3541ms  3391ms 145ms+2000us 0/0
     02:01 2016-02-23 23:43:57 : DONE  69K    524288 5632K 3567ms  3416ms 149ms+3000us 0/0
    Query [21] insert into a select 1 from a :
     01:01 2016-02-23 23:43:41 : DONE  6706    262144   55  1085ms    76us 1085ms+0us  0/0
     02:01 2016-02-23 23:43:41 : DONE  6706    262144   55  1090ms    67us 1091ms+0us  0/0
    Query [20] insert into a select 1 from a :
     01:01 2016-02-23 23:43:36 : DONE  6706    131072   55   532ms    77us 532ms+0us   0/0
     02:01 2016-02-23 23:43:36 : DONE  6706    131072   55   525ms    68us  526ms+0us  0/0
    Query [19] insert into a select 1 from a :
     01:01 2016-02-23 23:43:35 : DONE  6706     65536   55   251ms    77us   252ms+0us 0/0
     02:01 2016-02-23 23:43:35 : DONE  6706     65536   55   254ms    54us   255ms+0us 0/0
    Query [18] insert into a select 1 from a :
     01:01 2016-02-23 23:43:35 : DONE  6706     32768   55   122ms    58us   122ms+0us 0/0
     02:01 2016-02-23 23:43:35 : DONE  6706     32768   55   124ms    36us   124ms+0us 0/0
    Query [17] insert into a select 1 from a :
     01:01 2016-02-23 23:43:35 : DONE  6706      16384  55    66ms    22us    65ms+0us 0/0
     02:01 2016-02-23 23:43:35 : DONE  6706      16384  55    62ms    34us    63ms+0us 0/0
    Query [16] insert into a select 1 from a :
     01:01 2016-02-23 23:43:34 : DONE  6706       8192  55    39ms    57us    39ms+0us 0/0
     02:01 2016-02-23 23:43:34 : DONE  6706       8192  55    42ms    24us    42ms+0us 0/0
     
By default, the xlog command does not output records for any disconnected clients, or queries against the xsql_stat table. However these additional statistics can be displayed by specifying the all parameter. For example:
     
    XSQL>xlog all
    Node 127.0.0.1:5000 (shard 1) :
    Timestamp            State UsedMem  nRows  nBytes ExecTime TxTime CPUUsage   I/O        SQL
    Client 127.0.0.1:38800 (ID 48885306639241, connected) :
    2016-02-23 23:43:35 : DONE   6706   32768   55     122ms    58us  122ms+0us  0/0        18:insert into a select 1 from a
    2016-02-23 23:43:35 : DONE   6706   65536   55     251ms    77us  252ms+0us  0/0        19:insert into a select 1 from a
    2016-02-23 23:43:36 : DONE   6706  131072   55     532ms    77us  532ms+0us  0/0        20:insert into a select 1 from a
    2016-02-23 23:43:41 : DONE   6706  262144   55    1085ms    76us 1085ms+0us  0/0        21:insert into a select 1 from a
    2016-02-23 23:43:57 : DONE   69K   524288 5632K   3541ms  3391ms 145ms+2000us 0/0        22:select * from a
    2016-02-24 01:22:03 : DONE   76K       10  2627    220us    45us  0us+0us     0/0        23:select * from xsql_stat
    2016-02-24 01:22:12 : DONE   76K       10  2634    191us    48us  0us+0us     0/0        25:select * from xsql_stat
    2016-02-24 01:24:20 : DONE   76K       10  2641    187us    49us  0us+0us     0/0        27:select * from xsql_stat
    2016-02-24 01:28:54 : DONE   76K       10  2648    204us    56us  0us+0us     0/0        29:select * from xsql_stat
    2016-02-24 01:31:13 :ACTIVE  67K        0     0     76us     0us  0us+0us     0/0        31:select * from xsql_stat
    Client 127.0.0.1:39011 (ID 48891781117793, disconnected) :
    2016-02-24 01:31:08 : DONE   70K        1   432    211us    37us  0us+0us     0/0        1:select * from Metatable
    Node 127.0.0.1:5001 (shard 2) :
    Timestamp            State UsedMem  nRows  nBytes ExecTime TxTime CPUUsage   I/O        SQL
    Client 127.0.0.1:57335 (ID 48885306639241, connected) :
    2016-02-23 23:43:35 : DONE   6706   32768     55    124ms    36us  124ms+0us  0/0        18:insert into a select 1 from a
    2016-02-23 23:43:35 : DONE   6706   65536     55    254ms    54us   255ms+0us 0/0        19:insert into a select 1 from a
    2016-02-23 23:43:36 : DONE   6706  131072     55    525ms    68us   526ms+0us 0/0        20:insert into a select 1 from a
    2016-02-23 23:43:41 : DONE   6706  262144     55   1090ms    67us  1091ms+0us 0/0        21:insert into a select 1 from a
    2016-02-23 23:43:57 : DONE    69K  524288  5632K   3567ms  3416ms 149ms+3000us 0/0        22:select * from a
    2016-02-24 01:22:03 : DONE    76K      10   2627    220us    45us    0us+0us   0/0        24:select * from xsql_stat
    2016-02-24 01:22:12 : DONE    76K      10   2634    152us    52us     0us+0us  0/0        26:select * from xsql_stat
    2016-02-24 01:24:20 : DONE    76K      10   2641    180us    65us     0us+0us  0/0        28:select * from xsql_stat
    2016-02-24 01:28:54 : DONE    76K      10   2648    150us    49us     0us+0us  0/0        30:select * from xsql_stat
    2016-02-24 01:31:13 :ACTIVE   67K       0      0     50us     0us     0us+0us  0/0        32:select * from xsql_stat
    Client 127.0.0.1:57546 (ID 48891781117793, disconnected) :
    2016-02-24 01:31:08 : DONE    70K       1      432   181us    30us    0us+0us  0/0
    1:select * from Metatable
     
Command trace

Some statistics can be also displayed after each query by turning on the trace feature (command trace on). Enabling trace shows the statement being executed and elapsed time. For example:
 
    XSQL>trace on
    XSQL>select * from Account;
    Execute statement: select * from Account
    userid  name    lastlog
    -----------------------------------------------------------------------
    101     Dennis Hamer    01/23/15 14:15:03
    102     Edith Jackson   02/12/15 19:30:16
    103     Eric Harmon     02/14/15 09:34:47
    Selected records: 3
    Elapsed time: 0
    XSQL>insert into Account values (104, 'James Taylor', '2015-03-30 19:24:27');
    Execute statement: insert into Account values (104, 'James Taylor', '2015-03-30
    19:24:27')
    Update 1 records
    Elapsed time: 0
    XSQL>delete from Account where userid = 104;
    Execute statement: delete from Account where userid = 104
    Tree index search through table 'Account' < userid >
    expression: (Eq (Load (Table Account).userid) 104)
    Update 1 records
    Elapsed time: 0
     
When using the DistibutedSqlEngine with two shards (on ports 5000 and 5001) the trace output looks like the following:
 
    Shard:Node Used Memory  nRows    nBytes   Exec.Time  Transmit.Time  Host:Port
    1:1           71161   524288   5767674     3541205        3391115  127.0.0.1:5000
    2:1           71161   524288   5767674     3567462        3416186  127.0.0.1:5001
     
(Note that in the example above most of the time was spent in network transmission.)

Accessing statistics from a Python client

Server query statistics can also be retrieved using a Python client to display statistics contained in the Python dictionary. This is done by using the stats member of the connection object. For example:
 
    Print “Server stats: %s” % conn.stats
     
This will print out a line like the following:
     
    Server stats: {'execution_time': 158L, 'transmission_time': 0L, 'result_size_rows': 2L,'result_size_bytes': 137L, 'memory': 72356L}
     
Creating and saving log files

If a database fatal error has occurred or one of the fatal signals have been intercepted (SIGSEGV, SIGBUS, SIGILL, SIGFPE), all collected logs are written to an external file with a name formatted as follows: xlogs_YYYYMMDD_HHmmss_<PID>.txt.

On Linux platforms, files with names like xsql_YYYYMMDD_HHmmss_<PID>_<TID>.dmp are used to store backtraces of all active tasks. On Windows, minidump files are created. This is a standard Windows form of keeping backtraces and other information related to failed processes. (Unfortunately in order to view the dump files it is necessary to utilize the associated pdb files, which must be also saved).

These log files can also be created on demand by calling the xsql_dumplog() function. For example:
 
    select xsql_dumplog('my_log.txt');
     
Likewise the dumplog command can be invoked:
 
    XSQL>dumplog mylog.txt
    Logs are successfully dumped
     
Logging xSQL sessions

It can be useful to record a session of xSQL operations. The logsession on|off [<filename>] command creates a session file and writes the complete output from a session into it. (Note that the output is not affected by the seqformat and arrayformat options - it always saves all elements of sequences and arrays in the long format.) If a filename is not specified, xSQL creates a file with the name xsql.session.<curr_epoch_time>. It is possible to switch session logging on and off at runtime several times. For example:
 
    XSQL>logsession on "mysession.log"
    XSQL>select * from SomeTable;
    XSQL>logsession off
    XSQL>select * from TempTable;
    XSQL>logsession on "mysession.log"
     
Connection Lock Information

As explained in page Connection Lock Profiling, the locking profile is output from the call to stop_profile()consists of the percent, number of hits and the current wait event. In addition, the following information is available from the ConnectionInfo table with a simple query like the following:
 
    XSQL>select * from ConnectionInfo;
    Id	Pid	Tid	Status	SqlStmt	SubTransLevel WaitEvent	Snapshot
    -------------------------------------------------------
    0	14052	140452212647744	Running	select * from ConnectionInfo	1	NONE	0
    1	14053	139944457815872	Idle	commit transaction	0 NONE	0
 
    Selected records: 2
     
where the columns have the following meaning:

Id: the connection identifier

Pid: the process identifier (as reported by mco_get_pid())

Tid: the thread identifier (as reported by mco_get_thread_id())

Status: one of the following: Idle, Idle in transaction or Running

SqlStmt: the text of the last executed SQL statement (truncated to 128 bytes)

SubTransLevel: the current transaction nesting level

WaitEvent: the wait event name on which the connection is currently waiting

Snapshot: the transaction's active snapshot number

(Note that, to be able to use this function, it is necessary to use xSQL server, or connect to a shared memory database.)

This information is obtained without any locking, so it's consistency is not guaranteed (for example the query text may not be correct or the transaction state is not consistent with nesting level). But it can not cause a crash of the application.

xSQL Statistics Logging

For an overview see page xSQL Server Instrumentation

Statistics Logging

Pseudo-table xsql_stat

Function xsql_stat()

Function xsql_show_log(int)

Command xlog

Command trace

Accessing statistics from a Python client

Creating and saving log files

Logging xSQL sessions

Connection Lock Information