# 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.