How to get query timing in Tarantool like in other DBMS

Question

In MySQL/PostgreSQL/Oracle/MSSQL there's always duration in every query executed "Query completed in 0.23ms" or "Elapsed 0.001s" or at least when "EXPLAIN" or "EXPLAIN ANALYZE" the timings are shown. How to do this in tarantool client? (tarantoolctl connect 3301)

For example with EXPLAIN QUERY PLAN doesn't show the timing at all:

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, GREATEST(1,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, 0, 0, 'SEARCH TABLE userlistings USING PRIMARY KEY (user_id=?) (~10 rows)']
  - [2, 0, 0, 'SEARCH TABLE userlistings USING PRIMARY KEY (user_id=?) (~10 rows)']
  - [3, 0, 0, 'SEARCH TABLE usercats USING PRIMARY KEY (user_id=?) (~10 rows)']
  - [4, 0, 0, 'SEARCH TABLE usercats USING PRIMARY KEY (user_id=?) (~10 rows)']
  - [0, 0, 0, 'SEARCH TABLE listings USING COVERING INDEX ref_type (ref_type=?) (~10
      rows)']
  - [0, 1, 1, 'SCAN SUBQUERY 1 (~1 row)']
  - [0, 2, 2, 'SCAN SUBQUERY 2 (~1 row)']
  - [0, 3, 3, 'SCAN SUBQUERY 3 (~1 row)']
  - [0, 4, 4, 'SCAN SUBQUERY 4 (~1 row)']
  - [0, 0, 0, 'USE TEMP B-TREE FOR ORDER BY']
...

or in EXPLAIN also doesn't show any timing/duration:

box.execute "explain \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, GREATEST(1,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: 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', 0, 324, 0, '', '00', null]
  - [1, 'Integer', 18, 1, 0, '', '00', null]
  - [2, 'Once', 0, 18, 0, '', '00', null]
  - [3, 'OpenTEphemeral', 2, 3, 0, 'k(2,B,B)', '00', null]
  - [4, 'IteratorOpen', 1, 0, 2, '', '00', null]
  - [5, 'IteratorOpen', 11, 0, 0, 'space<name=userlistings>', '02', null]
  - [6, 'String8', 0, 3, 0, 'af07e444-44f3-4116-833e-90af7f24ffa0', '00', null]
  - [7, 'ApplyType', 3, 1, 0, "\x02", '00', null]
  - [8, 'SeekGE', 11, 18, 3, '1', '00', null]
  - [9, 'IdxGT', 11, 18, 3, '1', '00', null]
  - [10, 'Column', 11, 1, 4, '', '00', null]
  - [11, 'Column', 11, 2, 5, '', '00', null]
  - [12, 'MakeRecord', 4, 2, 6, '', '01', null]
  - [13, 'NextIdEphemeral', 2, 10, 0, '', '00', null]
  - [14, 'Copy', 4, 8, 1, '', '00', null]
  - [15, 'MakeRecord', 8, 3, 7, '', '01', null]
  - [16, 'IdxInsert', 7, 2, 0, '', '00', null]
  - [17, 'Next', 11, 9, 0, '', '00', null]
  - [18, 'Return', 1, 0, 0, '', '00', null]
  - [19, 'Integer', 42, 11, 0, '', '00', null]
  - [20, 'Once', 0, 42, 0, '', '00', null]
  - [21, 'OpenTEphemeral', 12, 2, 0, 'k(1,B)', '00', null]
  - [22, 'IteratorOpen', 2, 0, 12, '', '00', null]
  - [23, 'Null', 0, 13, 14, '', '00', null]
  - [24, 'IteratorOpen', 12, 0, 0, 'space<name=userlistings>', '02', null]
  - [25, 'String8', 0, 15, 0, 'af07e444-44f3-4116-833e-90af7f24ffa0', '00', null]
  - [26, 'ApplyType', 15, 1, 0, "\x02", '00', null]
  - [27, 'SeekGE', 12, 33, 15, '1', '00', null]
  - [28, 'IdxGT', 12, 33, 15, '1', '00', null]
  - [29, 'Column', 12, 2, 16, '', '00', null]
  - [30, 'CollSeq', 0, 0, 0, '(binary)', '00', null]
  - [31, 'AggStep0', 0, 16, 13, 'MAX(1)', '01', null]
  - [32, 'Next', 12, 28, 0, '', '00', null]
  - [33, 'AggFinal', 13, 1, 0, 'MAX(1)', '00', null]
  - [34, 'Copy', 13, 19, 0, '', '00', null]
  - [35, 'CollSeq', 0, 0, 0, '({type = binary})', '00', null]
  - [36, 'BuiltinFunction0', 1, 18, 17, 'GREATEST(-1)', '02', null]
  - [37, 'MakeRecord', 17, 1, 16, '', '01', null]
  - [38, 'NextIdEphemeral', 12, 22, 0, '', '00', null]
  - [39, 'Copy', 17, 21, 0, '', '00', null]
  - [40, 'MakeRecord', 21, 2, 20, '', '01', null]
  - [41, 'IdxInsert', 20, 12, 0, '', '00', null]
  - [42, 'Return', 11, 0, 0, '', '00', null]
  - [43, 'Integer', 62, 23, 0, '', '00', null]
  - [44, 'Once', 0, 62, 0, '', '00', null]
  - [45, 'OpenTEphemeral', 24, 5, 0, 'k(4,B,B,B,B)', '00', null]
  - [46, 'IteratorOpen', 3, 0, 24, '', '00', null]
  - [47, 'IteratorOpen', 13, 0, 0, 'space<name=usercats>', '02', null]
  - [48, 'String8', 0, 25, 0, 'af07e444-44f3-4116-833e-90af7f24ffa0', '00', null]
  - [49, 'ApplyType', 25, 1, 0, "\x02", '00', null]
  - [50, 'SeekGE', 13, 62, 25, '1', '00', null]
  - [51, 'IdxGT', 13, 62, 25, '1', '00', null]
  - [52, 'Column', 13, 1, 26, '', '00', null]
  - [53, 'Column', 13, 5, 27, '', '00', null]
  - [54, 'Column', 13, 4, 28, '', '00', null]
  - [55, 'Column', 13, 3, 29, '', '00', null]
  - [56, 'MakeRecord', 26, 4, 30, '', '01', null]
  - [57, 'NextIdEphemeral', 24, 36, 0, '', '00', null]
  - [58, 'Copy', 26, 32, 3, '', '00', null]
  - [59, 'MakeRecord', 32, 5, 31, '', '01', null]
  - [60, 'IdxInsert', 31, 24, 0, '', '00', null]
  - [61, 'Next', 13, 51, 0, '', '00', null]
  - [62, 'Return', 23, 0, 0, '', '00', null]
  - [63, 'Integer', 100, 37, 0, '', '00', null]
  - [64, 'Once', 0, 100, 0, '', '00', null]
  - [65, 'OpenTEphemeral', 38, 4, 0, 'k(3,B,B,B)', '00', null]
  - [66, 'IteratorOpen', 4, 0, 38, '', '00', null]
  - [67, 'Null', 0, 39, 44, '', '00', null]
  - [68, 'IteratorOpen', 14, 0, 0, 'space<name=usercats>', '02', null]
  - [69, 'String8', 0, 45, 0, 'af07e444-44f3-4116-833e-90af7f24ffa0', '00', null]
  - [70, 'ApplyType', 45, 1, 0, "\x02", '00', null]
  - [71, 'SeekGE', 14, 83, 45, '1', '00', null]
  - [72, 'IdxGT', 14, 83, 45, '1', '00', null]
  - [73, 'Column', 14, 5, 46, '', '00', null]
  - [74, 'CollSeq', 0, 0, 0, '(binary)', '00', null]
  - [75, 'AggStep0', 0, 46, 39, 'MAX(1)', '01', null]
  - [76, 'Column', 14, 4, 46, '', '00', null]
  - [77, 'CollSeq', 0, 0, 0, '(binary)', '00', null]
  - [78, 'AggStep0', 0, 46, 40, 'MAX(1)', '01', null]
  - [79, 'Column', 14, 3, 46, '', '00', null]
  - [80, 'CollSeq', 0, 0, 0, '(binary)', '00', null]
  - [81, 'AggStep0', 0, 46, 41, 'MAX(1)', '01', null]
  - [82, 'Next', 14, 72, 0, '', '00', null]
  - [83, 'AggFinal', 39, 1, 0, 'MAX(1)', '00', null]
  - [84, 'AggFinal', 40, 1, 0, 'MAX(1)', '00', null]
  - [85, 'AggFinal', 41, 1, 0, 'MAX(1)', '00', null]
  - [86, 'Copy', 39, 51, 0, '', '00', null]
  - [87, 'CollSeq', 0, 0, 0, '({type = binary})', '00', null]
  - [88, 'BuiltinFunction0', 1, 50, 47, 'GREATEST(-1)', '02', null]
  - [89, 'Copy', 40, 53, 0, '', '00', null]
  - [90, 'CollSeq', 0, 0, 0, '({type = binary})', '00', null]
  - [91, 'BuiltinFunction0', 1, 52, 48, 'GREATEST(-1)', '02', null]
  - [92, 'Copy', 41, 55, 0, '', '00', null]
  - [93, 'CollSeq', 0, 0, 0, '({type = binary})', '00', null]
  - [94, 'BuiltinFunction0', 1, 54, 49, 'GREATEST(-1)', '02', null]
  - [95, 'MakeRecord', 47, 3, 46, '', '01', null]
  - [96, 'NextIdEphemeral', 38, 60, 0, '', '00', null]
  - [97, 'Copy', 47, 57, 2, '', '00', null]
  - [98, 'MakeRecord', 57, 4, 56, '', '01', null]
  - [99, 'IdxInsert', 56, 38, 0, '', '00', null]
  - [100, 'Return', 37, 0, 0, '', '00', null]
  - [101, 'OpenTEphemeral', 61, 52, 0, 'k(1,-B)', '00', null]
  - [102, 'IteratorOpen', 15, 0, 61, '', '00', null]
  - [103, 'Integer', 5, 62, 0, '', '00', null]
  - [104, 'MustBeInt', 62, 107, 0, '', '00', null]
  - [105, 'Integer', 0, 63, 0, '', '00', null]
  - [106, 'Ge', 63, 109, 62, '', '00', null]
  - [107, 'SetDiag', 159, 0, 0, 'Failed to execute SQL statement: Only positive integers
      are allowed in the LIMIT clause', '00', null]
  - [108, 'Halt', -1, 0, 0, '', '00', null]
  - [109, 'Eq', 63, 323, 62, '', '00', null]
  - [110, 'Integer', 0, 64, 0, '', '00', null]
  - [111, 'MustBeInt', 64, 114, 0, '', '00', null]
  - [112, 'Integer', 0, 63, 0, '', '00', null]
  - [113, 'Ge', 63, 116, 64, '', '00', null]
  - [114, 'SetDiag', 159, 0, 0, 'Failed to execute SQL statement: Only positive integers
      are allowed in the OFFSET clause', '00', null]
  - [115, 'Halt', -1, 0, 0, '', '00', null]
  - [116, 'OffsetLimit', 62, 65, 64, '', '00', null]
  - [117, 'IteratorOpen', 16, 1, 0, 'space<name=listings>', '02', null]
  - [118, 'Integer', 1, 66, 0, '', '00', null]
  - [119, 'IsNull', 66, 121, 0, '', '00', null]
  - [120, 'MustBeInt', 66, 268, 0, '', '00', null]
  - [121, 'SeekGE', 16, 268, 66, '1', '00', null]
  - [122, 'IdxGT', 16, 268, 66, '1', '00', null]
  - [123, 'Integer', 0, 67, 0, '', '00', null]
  - [124, 'Rewind', 1, 264, 0, '', '00', null]
  - [125, 'Column', 16, 0, 63, '', '00', null]
  - [126, 'Column', 1, 0, 68, '', '00', null]
  - [127, 'Ne', 68, 263, 63, '({type = binary})', '18', null]
  - [128, 'Integer', 1, 67, 0, '', '00', null]
  - [129, 'Rewind', 2, 263, 0, '', '00', null]
  - [130, 'Integer', 0, 69, 0, '', '00', null]
  - [131, 'Rewind', 3, 259, 0, '', '00', null]
  - [132, 'Column', 16, 22, 68, '', '00', null]
  - [133, 'Column', 3, 0, 63, '', '00', null]
  - [134, 'Ne', 63, 258, 68, '({type = binary})', '18', null]
  - [135, 'Integer', 1, 69, 0, '', '00', null]
  - [136, 'Rewind', 4, 258, 0, '', '00', null]
  - [137, 'Column', 16, 0, 72, '', '00', null]
  - [138, 'Column', 16, 1, 73, '', '00', null]
  - [139, 'Column', 16, 2, 74, '', '00', null]
  - [140, 'Column', 16, 3, 75, '', '00', null]
  - [141, 'Column', 16, 4, 76, '', '00', null]
  - [142, 'Column', 16, 5, 77, '', '00', null]
  - [143, 'Column', 16, 6, 78, '', '00', null]
  - [144, 'Column', 16, 7, 79, '', '00', null]
  - [145, 'Column', 16, 8, 80, '', '00', null]
  - [146, 'Column', 16, 9, 81, '', '00', null]
  - [147, 'Column', 16, 10, 82, '', '00', null]
  - [148, 'Column', 16, 11, 83, '', '00', null]
  - [149, 'Column', 16, 12, 84, '', '00', null]
  - [150, 'Column', 16, 13, 85, '', '00', null]
  - [151, 'Column', 16, 14, 86, '', '00', null]
  - [152, 'Column', 16, 15, 87, '', '00', null]
  - [153, 'Column', 16, 16, 88, '', '00', null]
  - [154, 'Column', 16, 17, 89, '', '00', null]
  - [155, 'Column', 16, 18, 90, '', '00', null]
  - [156, 'Column', 16, 19, 91, '', '00', null]
  - [157, 'Column', 16, 20, 92, '', '00', null]
  - [158, 'Column', 16, 21, 93, '', '00', null]
  - [159, 'Column', 16, 22, 94, '', '00', null]
  - [160, 'Column', 16, 23, 95, '', '00', null]
  - [161, 'Column', 16, 24, 96, '', '00', null]
  - [162, 'Column', 16, 25, 97, '', '00', null]
  - [163, 'Column', 16, 26, 98, '', '00', null]
  - [164, 'Column', 16, 27, 99, '', '00', null]
  - [165, 'Column', 16, 28, 100, '', '00', null]
  - [166, 'Column', 16, 29, 101, '', '00', null]
  - [167, 'Column', 16, 30, 102, '', '00', null]
  - [168, 'Column', 16, 31, 103, '', '00', null]
  - [169, 'Column', 16, 32, 104, '', '00', null]
  - [170, 'Column', 16, 33, 105, '', '00', null]
  - [171, 'Column', 16, 34, 106, '', '00', null]
  - [172, 'Column', 16, 35, 107, '', '00', null]
  - [173, 'Column', 16, 36, 108, '', '00', null]
  - [174, 'Column', 16, 37, 109, '', '00', null]
  - [175, 'Column', 16, 38, 110, '', '00', null]
  - [176, 'Column', 16, 39, 111, '', '00', null]
  - [177, 'Column', 1, 0, 112, '', '00', null]
  - [178, 'Column', 1, 1, 113, '', '00', null]
  - [179, 'Column', 2, 0, 114, '', '00', null]
  - [180, 'Column', 3, 0, 115, '', '00', null]
  - [181, 'Column', 3, 1, 116, '', '00', null]
  - [182, 'Column', 3, 2, 117, '', '00', null]
  - [183, 'Column', 3, 3, 118, '', '00', null]
  - [184, 'Column', 4, 0, 119, '', '00', null]
  - [185, 'Column', 4, 1, 120, '', '00', null]
  - [186, 'Column', 4, 2, 121, '', '00', null]
  - [187, 'Column', 16, 35, 126, '', '00', null]
  - [188, 'SCopy', 114, 132, 0, '', '00', null]
  - [189, 'NotNull', 132, 191, 0, '', '00', null]
  - [190, 'Integer', 1, 132, 0, '', '00', null]
  - [191, 'SCopy', 113, 133, 0, '', '00', null]
  - [192, 'NotNull', 133, 194, 0, '', '00', null]
  - [193, 'Integer', 0, 133, 0, '', '00', null]
  - [194, 'Subtract', 133, 132, 131, '', '00', null]
  - [195, 'SCopy', 114, 133, 0, '', '00', null]
  - [196, 'NotNull', 133, 198, 0, '', '00', null]
  - [197, 'Integer', 1, 133, 0, '', '00', null]
  - [198, 'Divide', 133, 131, 130, '', '00', null]
  - [199, 'Multiply', 134, 130, 129, '', '00', null]
  - [200, 'Multiply', 135, 129, 128, '', '00', null]
  - [201, 'Divide', 136, 128, 127, '', '00', null]
  - [202, 'Add', 127, 126, 125, '', '00', null]
  - [203, 'Column', 16, 7, 139, '', '00', null]
  - [204, 'Subtract', 140, 139, 138, '', '00', null]
  - [205, 'BuiltinFunction0', 0, 138, 132, 'ABS(1)', '01', null]
  - [206, 'Subtract', 132, 137, 131, '', '00', null]
  - [207, 'Divide', 141, 131, 133, '', '00', null]
  - [208, 'Column', 16, 8, 143, '', '00', null]
  - [209, 'Subtract', 144, 143, 139, '', '00', null]
  - [210, 'BuiltinFunction0', 0, 139, 138, 'ABS(1)', '01', null]
  - [211, 'Subtract', 138, 142, 132, '', '00', null]
  - [212, 'Divide', 145, 132, 131, '', '00', null]
  - [213, 'Add', 131, 133, 130, '', '00', null]
  - [214, 'Multiply', 134, 130, 129, '', '00', null]
  - [215, 'Multiply', 146, 129, 128, '', '00', null]
  - [216, 'Divide', 136, 128, 127, '', '00', null]
  - [217, 'Add', 127, 125, 124, '', '00', null]
  - [218, 'SCopy', 118, 132, 0, '', '00', null]
  - [219, 'NotNull', 132, 221, 0, '', '00', null]
  - [220, 'Integer', 0, 132, 0, '', '00', null]
  - [221, 'SCopy', 121, 138, 0, '', '00', null]
  - [222, 'NotNull', 138, 224, 0, '', '00', null]
  - [223, 'Integer', 1, 138, 0, '', '00', null]
  - [224, 'Divide', 138, 132, 133, '', '00', null]
  - [225, 'Multiply', 134, 133, 131, '', '00', null]
  - [226, 'Multiply', 147, 131, 130, '', '00', null]
  - [227, 'Divide', 136, 130, 129, '', '00', null]
  - [228, 'Add', 129, 124, 68, '', '00', null]
  - [229, 'SCopy', 117, 138, 0, '', '00', null]
  - [230, 'NotNull', 138, 232, 0, '', '00', null]
  - [231, 'Integer', 0, 138, 0, '', '00', null]
  - [232, 'SCopy', 120, 132, 0, '', '00', null]
  - [233, 'NotNull', 132, 235, 0, '', '00', null]
  - [234, 'Integer', 1, 132, 0, '', '00', null]
  - [235, 'Divide', 132, 138, 133, '', '00', null]
  - [236, 'Multiply', 134, 133, 131, '', '00', null]
  - [237, 'Multiply', 135, 131, 130, '', '00', null]
  - [238, 'Divide', 136, 130, 124, '', '00', null]
  - [239, 'Add', 124, 68, 63, '', '00', null]
  - [240, 'SCopy', 116, 132, 0, '', '00', null]
  - [241, 'NotNull', 132, 243, 0, '', '00', null]
  - [242, 'Integer', 0, 132, 0, '', '00', null]
  - [243, 'SCopy', 119, 138, 0, '', '00', null]
  - [244, 'NotNull', 138, 246, 0, '', '00', null]
  - [245, 'Integer', 1, 138, 0, '', '00', null]
  - [246, 'Divide', 138, 132, 133, '', '00', null]
  - [247, 'Multiply', 134, 133, 131, '', '00', null]
  - [248, 'Multiply', 147, 131, 130, '', '00', null]
  - [249, 'Divide', 136, 130, 68, '', '00', null]
  - [250, 'Add', 68, 63, 70, '', '00', null]
  - [251, 'Sequence', 15, 71, 0, '', '00', null]
  - [252, 'MakeRecord', 70, 52, 123, '', '00', null]
  - [253, 'IdxInsert', 123, 61, 0, '', '00', null]
  - [254, 'IfNotZero', 65, 257, 0, '', '00', null]
  - [255, 'Rewind', 15, 256, 0, '', '00', null]
  - [256, 'Delete', 15, 0, 0, '', '00', null]
  - [257, 'Next', 4, 137, 0, '', '01', null]
  - [258, 'Next', 3, 132, 0, '', '01', null]
  - [259, 'IfPos', 69, 262, 0, '', '00', null]
  - [260, 'NullRow', 3, 0, 0, '', '00', null]
  - [261, 'Goto', 0, 135, 0, '', '00', null]
  - [262, 'Next', 2, 130, 0, '', '01', null]
  - [263, 'Next', 1, 125, 0, '', '01', null]
  - [264, 'IfPos', 67, 267, 0, '', '00', null]
  - [265, 'NullRow', 1, 0, 0, '', '00', null]
  - [266, 'Goto', 0, 128, 0, '', '00', null]
  - [267, 'Next', 16, 122, 1, '', '00', null]
  - [268, 'Last', 15, 323, 0, '', '00', null]
  - [269, 'IfPos', 64, 322, 1, '', '00', null]
  - [270, 'Column', 15, 0, 72, '', '00', null]
  - [271, 'Column', 15, 2, 73, '', '00', null]
  - [272, 'Column', 15, 3, 74, '', '00', null]
  - [273, 'Column', 15, 4, 75, '', '00', null]
  - [274, 'Column', 15, 5, 76, '', '00', null]
  - [275, 'Column', 15, 6, 77, '', '00', null]
  - [276, 'Column', 15, 7, 78, '', '00', null]
  - [277, 'Column', 15, 8, 79, '', '00', null]
  - [278, 'Column', 15, 9, 80, '', '00', null]
  - [279, 'Column', 15, 10, 81, '', '00', null]
  - [280, 'Column', 15, 11, 82, '', '00', null]
  - [281, 'Column', 15, 12, 83, '', '00', null]
  - [282, 'Column', 15, 13, 84, '', '00', null]
  - [283, 'Column', 15, 14, 85, '', '00', null]
  - [284, 'Column', 15, 15, 86, '', '00', null]
  - [285, 'Column', 15, 16, 87, '', '00', null]
  - [286, 'Column', 15, 17, 88, '', '00', null]
  - [287, 'Column', 15, 18, 89, '', '00', null]
  - [288, 'Column', 15, 19, 90, '', '00', null]
  - [289, 'Column', 15, 20, 91, '', '00', null]
  - [290, 'Column', 15, 21, 92, '', '00', null]
  - [291, 'Column', 15, 22, 93, '', '00', null]
  - [292, 'Column', 15, 23, 94, '', '00', null]
  - [293, 'Column', 15, 24, 95, '', '00', null]
  - [294, 'Column', 15, 25, 96, '', '00', null]
  - [295, 'Column', 15, 26, 97, '', '00', null]
  - [296, 'Column', 15, 27, 98, '', '00', null]
  - [297, 'Column', 15, 28, 99, '', '00', null]
  - [298, 'Column', 15, 29, 100, '', '00', null]
  - [299, 'Column', 15, 30, 101, '', '00', null]
  - [300, 'Column', 15, 31, 102, '', '00', null]
  - [301, 'Column', 15, 32, 103, '', '00', null]
  - [302, 'Column', 15, 33, 104, '', '00', null]
  - [303, 'Column', 15, 34, 105, '', '00', null]
  - [304, 'Column', 15, 35, 106, '', '00', null]
  - [305, 'Column', 15, 36, 107, '', '00', null]
  - [306, 'Column', 15, 37, 108, '', '00', null]
  - [307, 'Column', 15, 38, 109, '', '00', null]
  - [308, 'Column', 15, 39, 110, '', '00', null]
  - [309, 'Column', 15, 40, 111, '', '00', null]
  - [310, 'Column', 15, 41, 112, '', '00', null]
  - [311, 'Column', 15, 42, 113, '', '00', null]
  - [312, 'Column', 15, 43, 114, '', '00', null]
  - [313, 'Column', 15, 44, 115, '', '00', null]
  - [314, 'Column', 15, 45, 116, '', '00', null]
  - [315, 'Column', 15, 46, 117, '', '00', null]
  - [316, 'Column', 15, 47, 118, '', '00', null]
  - [317, 'Column', 15, 48, 119, '', '00', null]
  - [318, 'Column', 15, 49, 120, '', '00', null]
  - [319, 'Column', 15, 50, 121, '', '00', null]
  - [320, 'Column', 15, 51, 122, '', '00', null]
  - [321, 'ResultRow', 72, 51, 0, '', '00', null]
  - [322, 'Prev', 15, 269, 0, '', '00', null]
  - [323, 'Halt', 0, 0, 0, '', '00', null]
  - [324, 'Integer', 1, 18, 0, '', '00', null]
  - [325, 'Integer', 1, 50, 0, '', '00', null]
  - [326, 'Integer', 1, 52, 0, '', '00', null]
  - [327, 'Integer', 1, 54, 0, '', '00', null]
  - [328, 'Real', 0, 134, 0, '100', '00', null]
  - [329, 'Real', 0, 135, 0, '5.28000020980835', '00', null]
  - [330, 'Real', 0, 136, 0, '100.010002136', '00', null]
  - [331, 'Integer', 180, 137, 0, '', '00', null]
  - [332, 'Real', 0, 140, 0, '-5.796658992767334', '00', null]
  - [333, 'Real', 0, 141, 0, '360', '00', null]
  - [334, 'Integer', 360, 142, 0, '', '00', null]
  - [335, 'Real', 0, 144, 0, '106.4992752075195', '00', null]
  - [336, 'Real', 0, 145, 0, '720', '00', null]
  - [337, 'Real', 0, 146, 0, '22.28000068664551', '00', null]
  - [338, 'Integer', 0, 147, 0, '', '00', null]
  - [339, 'Goto', 0, 1, 0, '', '00', null]
...

the original query (previously using subqueries like (SELECT "max_click" FROM mopq) but it gives longer explain compared to 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"
        , GREATEST(1,MAX("purchase_interest")) "max_purchase"
        , GREATEST(1,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",1) * 100.0 * 0/100.010002136, *
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

this query took a bit weird duration (measured in the go program, but it would took much time to deploy each time I need change the query):

ref_type = 1 (3538 rows)  587ms
ref_type = 5 ( 886 rows)  142ms
ref_type = 3 ( 104 rows)    9ms
ref_type = 6 (1608 rows)  276ms

score 3 · Answer 1 · answered Feb 01 '21 at 14:29

Agreed that it's unfortunate and inconvenient, and we plan to make it more convenient in the rather short-term.

As a dirty work-around today I could suggest you to enable VDBE_PROFILE and recompile Tarantool, this would generate annotated with run-time information VDBE log of queries executed to the vdbe_profile.out file, where you would see both timings and counters.

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)

score 2 · Accepted Answer · answered Feb 01 '21 at 14:24

There's no native (i.e. SQL-like) way to measure query execution time. However, you are able to wrap your query in Lua function, which tracks time (using os Lua module). Example is taken from 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'

Feel free to open feature request on github: https://github.com/tarantool/tarantool/issues/new

`os.clock` is low resolution. Better to use `clock.time()` – Mons Anderson Feb 01 '21 at 16:34 — Mons Anderson, Feb 01 '21 at 16:34

Kokizzu · Answer 3 · 2021-02-01T15:06:12.617

Modified from NikitaRock's answer, create a helper function like this 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']
...

How to get query timing in Tarantool like in other DBMS

3 Answers3