如何解决如何像在其他 DBMS 中一样在 Tarantool 中获取查询时间
在 MySQL/PostgreSQL/Oracle/MSSQL 中，每次执行的查询总是有持续时间“查询在 0.23 毫秒内完成”或“经过 0.001 秒”，或者至少在“解释”或“解释分析”时显示时间。如何在 tarantool 客户端中执行此操作？ (tarantoolctl connect 3301)
例如 EXPLAIN QUERY PLAN 根本不显示时间：
box.execute "explain query plan \nWITH sc AS ( -- shown count\n\tSELECT \"ref_id\"\n\t\t,\"view_count\"\n\tFROM \"userlistings\"\n\tWHERE \"user_id\" = 'af07e444-44f3-4116-833e-90af7f24ffa0'\n),msc AS (\n\tSELECT GREATEST(1,MAX(\"view_count\")) \"max_view\"\n\tFROM sc\n)\n,\nopq AS ( \n\tSELECT \"cat_id\"\n\t\t,\"click_interest\" -- SPEC-Q\n\t\t,\"purchase_interest\" -- SPEC-P\n\t\t,\"message_interest\" -- SPEC-O\n\tFROM \"usercats\"\n\tWHERE \"user_id\" = 'af07e444-44f3-4116-833e-90af7f24ffa0'\n),mopq AS (\n\tSELECT GREATEST(1,MAX(\"click_interest\")) \"max_click\"\n\t\t,GREATEST(1,MAX(\"purchase_interest\")) \"max_purchase\"\n\t\t,MAX(\"message_interest\")) \"max_inquiry\"\n\tFROM opq\n)\nSELECT \"initial_cache\" \n+ (IFNULL(msc.\"max_view\",1) - IFNULL(sc.\"view_count\",0)) / IFNULL(msc.\"max_view\",1) * 100.0 * 5.28000020980835/100.010002136\n+ ((180-abs(\"lat\" - -5.796658992767334))/360.0 + (360-abs(\"long\" - 106.49927520751953))/720.0) * 100.0 * 22.280000686645508/100.010002136\n+ IFNULL(\"message_interest\",0) / IFNULL(mopq.\"max_inquiry\",1) * 100.0 * 0/100.010002136\n+ IFNULL(\"purchase_interest\",0) / IFNULL(mopq.\"max_purchase\",1) * 100.0 * 5.28000020980835/100.010002136\n+ IFNULL(\"click_interest\",0) / IFNULL(mopq.\"max_click\",1) * 100.0 * 0/100.010002136,*\nFROM \"listings\"\n\nLEFT JOIN sc\n\tON \"listings\".\"ref_id\" = sc.\"ref_id\"\nCROSS JOIN msc\n\nLEFT JOIN opq\n\tON \"listings\".\"categories\" = opq.\"cat_id\"\nCROSS JOIN mopq\n\nWHERE \"ref_type\" = 1\nORDER BY 1 DESC LIMIT 5 OFFSET 0"
---
- metadata:
- name: selectid
type: integer
- name: order
type: integer
- name: from
type: integer
- name: detail
type: text
rows:
- [1,'SEARCH TABLE userlistings USING PRIMARY KEY (user_id=?) (~10 rows)']
- [2,'SEARCH TABLE userlistings USING PRIMARY KEY (user_id=?) (~10 rows)']
- [3,'SEARCH TABLE usercats USING PRIMARY KEY (user_id=?) (~10 rows)']
- [4,'SEARCH TABLE usercats USING PRIMARY KEY (user_id=?) (~10 rows)']
- [0,'SEARCH TABLE listings USING COVERING INDEX ref_type (ref_type=?) (~10
rows)']
- [0,1,'SCAN SUBQUERY 1 (~1 row)']
- [0,2,'SCAN SUBQUERY 2 (~1 row)']
- [0,3,'SCAN SUBQUERY 3 (~1 row)']
- [0,4,'SCAN SUBQUERY 4 (~1 row)']
- [0,'USE TEMP B-TREE FOR ORDER BY']
...
或在 EXPLAIN 中也不显示任何时间/持续时间：
box.execute "explain \nWITH sc AS ( -- shown count\n\tSELECT \"ref_id\"\n\t\t,*\nFROM \"listings\"\n\nLEFT JOIN sc\n\tON \"listings\".\"ref_id\" = sc.\"ref_id\"\nCROSS JOIN msc\n\nLEFT JOIN opq\n\tON \"listings\".\"categories\" = opq.\"cat_id\"\nCROSS JOIN mopq\n\nWHERE \"ref_type\" = 1\nORDER BY 1 DESC LIMIT 5 OFFSET 0"
---
- metadata:
- name: addr
type: integer
- name: opcode
type: text
- name: p1
type: integer
- name: p2
type: integer
- name: p3
type: integer
- name: p4
type: text
- name: p5
type: text
- name: comment
type: text
rows:
- [0,'Init',324,'','00',null]
- [1,'Integer',18,null]
- [2,'Once',null]
- [3,'OpenTEphemeral','k(2,B,B)',null]
- [4,'IteratorOpen',null]
- [5,11,'space<name=userlistings>','02',null]
- [6,'String8','af07e444-44f3-4116-833e-90af7f24ffa0',null]
- [7,'ApplyType',"\x02",null]
- [8,'SeekGE','1',null]
- [9,'IdxGT',null]
- [10,'Column',null]
- [11,5,null]
- [12,'MakeRecord',6,'01',null]
- [13,'NextIdEphemeral',10,null]
- [14,'Copy',8,null]
- [15,7,null]
- [16,'IdxInsert',null]
- [17,'Next',9,null]
- [18,'Return',null]
- [19,42,null]
- [20,null]
- [21,12,'k(1,null]
- [22,null]
- [23,'Null',13,14,null]
- [24,null]
- [25,15,null]
- [26,null]
- [27,33,null]
- [28,null]
- [29,16,null]
- [30,'CollSeq','(binary)',null]
- [31,'AggStep0','MAX(1)',null]
- [32,28,null]
- [33,'AggFinal',null]
- [34,19,null]
- [35,'({type = binary})',null]
- [36,'BuiltinFunction0',17,'GREATEST(-1)',null]
- [37,null]
- [38,22,null]
- [39,21,null]
- [40,20,null]
- [41,null]
- [42,null]
- [43,62,23,null]
- [44,null]
- [45,24,'k(4,null]
- [46,null]
- [47,'space<name=usercats>',null]
- [48,25,null]
- [49,null]
- [50,null]
- [51,null]
- [52,26,null]
- [53,27,null]
- [54,null]
- [55,29,null]
- [56,30,null]
- [57,36,null]
- [58,32,null]
- [59,31,null]
- [60,null]
- [61,51,null]
- [62,null]
- [63,100,37,null]
- [64,null]
- [65,38,'k(3,null]
- [66,null]
- [67,39,44,null]
- [68,null]
- [69,45,null]
- [70,null]
- [71,83,null]
- [72,null]
- [73,46,null]
- [74,null]
- [75,null]
- [76,null]
- [77,null]
- [78,40,null]
- [79,null]
- [80,null]
- [81,41,null]
- [82,72,null]
- [83,null]
- [84,null]
- [85,null]
- [86,null]
- [87,null]
- [88,50,47,null]
- [89,53,null]
- [90,null]
- [91,52,48,null]
- [92,55,null]
- [93,null]
- [94,54,49,null]
- [95,null]
- [96,60,null]
- [97,57,null]
- [98,56,null]
- [99,null]
- [100,null]
- [101,61,-B)',null]
- [102,null]
- [103,null]
- [104,'MustBeInt',107,null]
- [105,63,null]
- [106,'Ge',109,null]
- [107,'SetDiag',159,'Failed to execute SQL statement: Only positive integers
are allowed in the LIMIT clause',null]
- [108,'Halt',-1,null]
- [109,'Eq',323,null]
- [110,64,null]
- [111,114,null]
- [112,null]
- [113,116,null]
- [114,'Failed to execute SQL statement: Only positive integers
are allowed in the OFFSET clause',null]
- [115,null]
- [116,'OffsetLimit',65,null]
- [117,'space<name=listings>',null]
- [118,66,null]
- [119,'IsNull',121,null]
- [120,268,null]
- [121,null]
- [122,null]
- [123,67,null]
- [124,'Rewind',264,null]
- [125,null]
- [126,68,null]
- [127,'Ne',263,'18',null]
- [128,null]
- [129,null]
- [130,69,null]
- [131,259,null]
- [132,null]
- [133,null]
- [134,258,null]
- [135,null]
- [136,null]
- [137,null]
- [138,73,null]
- [139,74,null]
- [140,75,null]
- [141,76,null]
- [142,77,null]
- [143,78,null]
- [144,79,null]
- [145,80,null]
- [146,81,null]
- [147,82,null]
- [148,null]
- [149,84,null]
- [150,85,null]
- [151,86,null]
- [152,87,null]
- [153,88,null]
- [154,89,null]
- [155,90,null]
- [156,91,null]
- [157,92,null]
- [158,93,null]
- [159,94,null]
- [160,95,null]
- [161,96,null]
- [162,97,null]
- [163,98,null]
- [164,99,null]
- [165,null]
- [166,101,null]
- [167,102,null]
- [168,103,null]
- [169,104,null]
- [170,105,null]
- [171,34,106,null]
- [172,35,null]
- [173,108,null]
- [174,null]
- [175,110,null]
- [176,111,null]
- [177,112,null]
- [178,113,null]
- [179,null]
- [180,115,null]
- [181,null]
- [182,117,null]
- [183,118,null]
- [184,119,null]
- [185,120,null]
- [186,null]
- [187,126,null]
- [188,'SCopy',132,null]
- [189,'NotNull',191,null]
- [190,null]
- [191,133,null]
- [192,194,null]
- [193,null]
- [194,'Subtract',131,null]
- [195,null]
- [196,198,null]
- [197,null]
- [198,'Divide',130,null]
- [199,'Multiply',134,129,null]
- [200,135,128,null]
- [201,136,127,null]
- [202,'Add',125,null]
- [203,139,null]
- [204,140,138,null]
- [205,'ABS(1)',null]
- [206,137,null]
- [207,141,null]
- [208,143,null]
- [209,144,null]
- [210,null]
- [211,142,null]
- [212,145,null]
- [213,null]
- [214,null]
- [215,146,null]
- [216,null]
- [217,124,null]
- [218,null]
- [219,221,null]
- [220,null]
- [221,null]
- [222,224,null]
- [223,null]
- [224,null]
- [225,null]
- [226,147,null]
- [227,null]
- [228,null]
- [229,null]
- [230,232,null]
- [231,null]
- [232,null]
- [233,235,null]
- [234,null]
- [235,null]
- [236,null]
- [237,null]
- [238,null]
- [239,null]
- [240,null]
- [241,243,null]
- [242,null]
- [243,null]
- [244,246,null]
- [245,null]
- [246,null]
- [247,null]
- [248,null]
- [249,null]
- [250,70,null]
- [251,'Sequence',71,null]
- [252,123,null]
- [253,null]
- [254,'IfNotZero',257,null]
- [255,256,null]
- [256,'Delete',null]
- [257,null]
- [258,null]
- [259,'IfPos',262,null]
- [260,'NullRow',null]
- [261,'Goto',null]
- [262,null]
- [263,null]
- [264,267,null]
- [265,null]
- [266,null]
- [267,122,null]
- [268,'Last',null]
- [269,322,null]
- [270,null]
- [271,null]
- [272,null]
- [273,null]
- [274,null]
- [275,null]
- [276,null]
- [277,null]
- [278,null]
- [279,null]
- [280,null]
- [281,null]
- [282,null]
- [283,null]
- [284,null]
- [285,null]
- [286,null]
- [287,null]
- [288,null]
- [289,null]
- [290,null]
- [291,null]
- [292,null]
- [293,null]
- [294,null]
- [295,null]
- [296,null]
- [297,null]
- [298,null]
- [299,null]
- [300,null]
- [301,null]
- [302,null]
- [303,null]
- [304,null]
- [305,null]
- [306,null]
- [307,null]
- [308,null]
- [309,null]
- [310,null]
- [311,null]
- [312,43,null]
- [313,null]
- [314,null]
- [315,null]
- [316,null]
- [317,null]
- [318,null]
- [319,null]
- [320,null]
- [321,'ResultRow',null]
- [322,'Prev',269,null]
- [323,null]
- [324,null]
- [325,null]
- [326,null]
- [327,null]
- [328,'Real','100',null]
- [329,'5.28000020980835',null]
- [330,'100.010002136',null]
- [331,180,null]
- [332,'-5.796658992767334',null]
- [333,'360',null]
- [334,360,null]
- [335,'106.4992752075195',null]
- [336,'720',null]
- [337,'22.28000068664551',null]
- [338,null]
- [339,null]
...
原始查询（以前使用像 (SELECT "max_click" FROM mopq) 这样的子查询，但与 explain 相比，它提供更长的 CROSS JOIN：
WITH sc AS ( -- shown count
SELECT "ref_id","view_count"
FROM "userlistings"
WHERE "user_id" = 'af07e444-44f3-4116-833e-90af7f24ffa0'
),msc AS (
SELECT GREATEST(1,MAX("view_count")) "max_view"
FROM sc
),opq AS (
SELECT "cat_id","click_interest" -- SPEC-Q,"purchase_interest" -- SPEC-P,"message_interest" -- SPEC-O
FROM "usercats"
WHERE "user_id" = 'af07e444-44f3-4116-833e-90af7f24ffa0'
),mopq AS (
SELECT GREATEST(1,MAX("click_interest")) "max_click",MAX("purchase_interest")) "max_purchase",MAX("message_interest")) "max_inquiry"
FROM opq
)
SELECT "initial_cache"
+ (IFNULL(msc."max_view",1) - IFNULL(sc."view_count",0)) / IFNULL(msc."max_view",1) * 100.0 * 5.28000020980835/100.010002136
+ ((180-abs("lat" - -5.796658992767334))/360.0 + (360-abs("long" - 106.49927520751953))/720.0) * 100.0 * 22.280000686645508/100.010002136
+ IFNULL("message_interest",0) / IFNULL(mopq."max_inquiry",1) * 100.0 * 0/100.010002136
+ IFNULL("purchase_interest",0) / IFNULL(mopq."max_purchase",1) * 100.0 * 5.28000020980835/100.010002136
+ IFNULL("click_interest",0) / IFNULL(mopq."max_click",*
FROM "listings"
LEFT JOIN sc
ON "listings"."ref_id" = sc."ref_id"
CROSS JOIN msc
LEFT JOIN opq
ON "listings"."categories" = opq."cat_id"
CROSS JOIN mopq
WHERE "ref_type" = 1
ORDER BY 1 DESC LIMIT 5 OFFSET 0
这个查询的持续时间有点奇怪（在 go 程序中测量，但每次我需要更改查询时都需要花费很多时间来部署）：
ref_type = 1 (3538 rows) 587ms
ref_type = 5 ( 886 rows) 142ms
ref_type = 3 ( 104 rows) 9ms
ref_type = 6 (1608 rows) 276ms
解决方法
没有原生的（即类似 SQL 的）方法来衡量查询执行时间。但是，您可以将查询包装在 Lua 函数中，该函数跟踪时间（使用 os Lua 模块）。示例取自 SQL reference：
function main_function()
local string_value,t,sql_statement
for i = 1,1000000,1 do
string_value = string_function()
sql_statement = "INSERT INTO tester VALUES (" .. i .. ",'" .. string_value .. "')"
box.execute(sql_statement)
end
end
start_time = os.clock()
main_function()
end_time = os.clock()
'insert done in ' .. end_time - start_time .. ' seconds'
随意在 github 上打开功能请求：https://github.com/tarantool/tarantool/issues/new
,同意这很不幸且不方便，我们计划在相当短的时间内使它更方便。
作为今天的一个肮脏的解决方法，我建议您启用 VDBE_PROFILE 并重新编译 Tarantool，这将生成带有运行时信息的注释，对 vdbe_profile.out 文件执行的查询的 VDBE 日志，您可以在其中会同时看到计时和计数器。
diff --git a/src/box/CMakeLists.txt b/src/box/CMakeLists.txt
index 999ac4749..0126f5af3 100644
--- a/src/box/CMakeLists.txt
+++ b/src/box/CMakeLists.txt
@@ -222,6 +222,7 @@ if(CMAKE_BUILD_TYPE STREQUAL "Debug")
add_definitions(-DSQL_DEBUG=1)
endif()
add_definitions(-DSQL_TEST=1)
+add_definitions(-DVDBE_PROFILE=1)
set(EXT_SRC_DIR ${CMAKE_SOURCE_DIR}/extra)
set(EXT_BIN_DIR ${CMAKE_BINARY_DIR}/extra)
根据 NikitaRock 的回答修改，创建一个像这样的辅助函数 T：
> function T(sql_statement)
start_time = os.clock()
res = box.execute(sql_statement)
end_time = os.clock()
return box.tuple.new(res,'Query done in ' .. string.format("%.2f",(end_time - start_time)*1000) .. ' ms')
end
> T 'SELECT COUNT(*) FROM "listings" WHERE "ref_type" = 6;'
---
- [{'metadata': [{'name': 'COLUMN_1','type': 'integer'}],'rows': [[1608]]},'Query
done in 0.49 ms']
...
版权声明：本文内容由互联网用户自发贡献，该文观点与技术仅代表作者本人。本站仅提供信息存储空间服务，不拥有所有权，不承担相关法律责任。如发现本站有涉嫌侵权/违法违规的内容， 请发送邮件至 dio@foxmail.com 举报，一经查实，本站将立刻删除。
