统计日志记录
当作为服务器运行时,xSQL 会收集信息,以便在无需将调试器附加到服务器进程的情况下检查服务器的状态。此外,还提供基本的连接锁定信息,以检查客户端连接的状态。
为了确保每个操作都能被准确记录,xSQL 会详细记录每次执行的语句信息。以下是具体记录的内容:
已连接客户端的 IP 地址和端口号
客户端当前状态:是否已成功连接或断开连接
服务器开始处理该语句的时间
语句的当前状态:
- ACTIVE:语句正在处理中
- DONE:语句已成功完成
- FAILED:语句在执行过程中遇到了问题
- CANCELED:语句因网络或其他原因被中断
执行的具体 SQL 语句
查询参数列表
如果语句失败或被中断,将记录相应的错误信息
语句执行期间的最大内存使用量(以字节为单位)
结果集大小:对于 SELECT 语句,记录返回的行数;对于 INSERT/UPDATE/DELETE 语句,记录受影响的行数
结果集传输大小(以字节为单位):从服务器发送到客户端的数据量(仅适用于 SELECT 语句)
语句执行的总时间(微秒),即从接收到语句到服务器完成结果集传输的时间
结果集传输的总时间(微秒),减去语句执行时间,可以得出服务器本地处理语句所需的时间
其他系统资源使用情况,包括:
用户空间 CPU 时间:语句在用户空间中占用的 CPU 时间
内核空间 CPU 时间:语句在内核空间中占用的 CPU 时间
读取字节数:从持久存储读取的数据量(不包括缓存读取)
写入字节数:写入持久存储的数据量
交换次数:语句执行期间的总交换空间大小
上下文切换次数:语句执行期间的上下文切换次数
这些统计信息由 xSQL 的配置参数 xlog_params
控制,并保存在伪表 xsql_stat
中(实际上是一个循环日志缓冲区)。如果您想查看日志记录的实际效果,可以在 samples\xsql\scripts
目录下的控制台窗口中启动 xSQL 服务器。
..\..\..\target\bin\xsql.exe -size 100m -p 5000 -c xsql.cfg
press Enter to stop SQL server
然后在单独的控制台窗口中,从目录 samples\xsql\scripts 以客户端形式运行 xSQL,并按如下方式执行脚本文件 index.sql :
..\..\..\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
现在可以使用 xlog 命令访问运行时统计信息:
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
或者直接查询伪表 xsql_stat:
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
或者通过调用函数 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
伪表 xsql_stat
xsql_stat 表的结构可以表示如下(每行对应单个 SQL 语句的执行):
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
);
xsql_stat()
函数 xsql_stat() 有两个布尔型参数 show_disconnected_clients 和 show_statistics_queries,它们分别决定是否显示已断开连接的客户端的统计信息以及是否显示针对 xsql_stat 表的查询统计信息。
该函数以结构体数组的形式返回信息,其中包含上述定义的字段集。(请注意,通过远程 SQL 引擎调用时,整个结果将作为一个非常长的数据包返回,所有这些字段都必须适合由配置文件中的 sql_comm_buffer 参数定义的通信缓冲区。如果收集了大量日志,很有可能收到“缓冲区太小”的错误。如果查询 xsql_stat 表而不是调用 xsql_stat() 函数,则接收的日志记录数量没有限制。)
xsql_show_log(int)
函数 xsql_show_log() 可以从远程客户端调用,以显示服务器日志的最后几行。它有一个参数 int n_lines,用于确定从服务器获取的输出行数。例如:
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
xlog 命令
命令 xlog 实现了查询“select * from xsql_stat...”,并且(默认情况下)首先按分片对结果进行分组,然后再按客户端 ID 分组。例如,如果有两个分片,可能会显示以下统计信息:
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
或者,可以指定参数 byquery,先按 clientID 对结果进行分组,然后再按每个分片的 queryID 进行分组。这样可以更轻松地查看不同分片上查询的执行统计信息。例如:
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
默认情况下,xlog 命令不会输出任何已断开连接的客户端的记录,也不会输出针对 xsql_stat 表的查询。不过,通过指定 all 参数,可以显示这些额外的统计信息。例如:
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
trace 命令
通过开启跟踪功能(命令跟踪开启),在每次查询后还可以显示一些统计信息。启用跟踪会显示正在执行的语句以及所花费的时间。例如:
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
使用分布式 SQL 引擎(在 5000 和 5001 端口上分别有两个分片)时,跟踪输出如下所示:
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
(请注意,在上述示例中,大部分时间都花在了网络传输上。)
从 Python 客户端访问统计信息
还可以使用 Python 客户端获取服务器查询统计信息,并将其显示在 Python 字典中。这是通过使用连接对象的 stats 成员来实现的。例如:
Print “Server stats: %s” % conn.stats
这将打印出类似以下的一行:
Server stats: {'execution_time': 158L, 'transmission_time': 0L, 'result_size_rows': 2L,'result_size_bytes': 137L, 'memory': 72356L}
创建和保存日志文件
如果数据库发生致命错误,或者截获了其中一种致命信号(SIGSEGV、SIGBUS、SIGILL、SIGFPE),则所有收集的日志都将写入一个外部文件,该文件的名称格式如下:xlogs_YYYYMMDD_HHmmss_<PID>.txt。
在 Linux 平台上,会使用类似 xsql_YYYYMMDD_HHmmss_<PID>_<TID>.dmp 这样的文件名来存储所有活动任务的回溯信息。在 Windows 系统中,则会创建 minidump 文件。这是 Windows 用于保存失败进程的回溯信息及其他相关信息的标准格式。(遗憾的是,要查看这些转储文件,必须使用相关的 pdb 文件,这些文件也必须保存下来)。
这些日志文件也可以通过调用 xsql_dumplog() 函数按需创建。例如:
select xsql_dumplog('my_log.txt');
同样,也可以调用 dumplog 命令:
XSQL>dumplog mylog.txt
Logs are successfully dumped
会话记录
记录 xSQL 操作会话可能会很有用。logsession on|off [<文件名>] 命令会创建一个会话文件,并将整个会话的完整输出写入其中。(请注意,输出不受 seqformat 和 arrayformat 选项的影响 - 它始终以长格式保存序列和数组的所有元素。)如果未指定文件名,xSQL 将创建一个名为 xsql.session.<当前纪元时间> 的文件。可以在运行时多次切换会话日志记录的开启和关闭状态。例如:
XSQL>logsession on "mysession.log"
XSQL>select * from SomeTable;
XSQL>logsession off
XSQL>select * from TempTable;
XSQL>logsession on "mysession.log"
连接锁定信息
正如在“连接锁定分析”页面中所解释的那样,从对 stop_profile() 的调用中输出的锁定分析结果包含百分比、命中次数以及当前等待事件。此外,通过如下简单的查询,还可以从 ConnectionInfo 表中获取以下信息:
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
其中各列的含义如下:
- Id:连接标识符
- Pid:进程标识符(由 mco_get_pid() 报告)
- Tid:线程标识符(由 mco_get_thread_id() 报告)
- Status:以下状态之一:空闲、空闲事务中或运行
- SqlStmt:上次执行的 SQL 语句文本(截断为 128 字节)
- SubTransLevel:当前事务嵌套级别
- WaitEvent:连接当前正在等待的等待事件名称
- Snapshot:事务的活动快照编号
请注意,要能够使用此函数,必须使用 xSQL 服务器,或者连接到共享内存数据库。
此信息是在没有任何锁定的情况下获取的,因此其一致性无法得到保证(例如查询文本可能不正确或事务状态与嵌套级别不一致)。但它不会导致应用程序崩溃。