query-optimizationdurationtarantool

How to get query timing in Tarantool like in other DBMS


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

Solution

  • 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