[Groonga-commit] groonga/groonga at 5bcacb6 [master] select logical_select: add more query logs

Back to archive index
Kouhei Sutou null+****@clear*****
Mon May 13 17:54:59 JST 2019


Kouhei Sutou	2019-05-13 17:54:59 +0900 (Mon, 13 May 2019)

  Revision: 5bcacb6476a3bac37bb1199f56840740dd32711f
  https://github.com/groonga/groonga/commit/5bcacb6476a3bac37bb1199f56840740dd32711f

  Message:
    select logical_select: add more query logs

  Modified files:
    lib/proc/proc_select.c
    plugins/sharding/dynamic_columns.rb
    plugins/sharding/logical_count.rb
    plugins/sharding/logical_range_filter.rb
    plugins/sharding/logical_select.rb
    test/command/suite/select/drilldown/plain/adjuster/filter.expected
    test/command/suite/select/drilldown/plain/adjuster/no_filter.expected
    test/command/suite/select/drilldown/plain/sort_keys.expected
    test/command/suite/select/drilldown/plain/sort_keys.test
    test/command/suite/select/drilldowns/adjuster/filter.expected
    test/command/suite/select/drilldowns/adjuster/no_filter.expected
    test/command/suite/select/drilldowns/columns/stage/initial/drilldown.expected
    test/command/suite/select/drilldowns/columns/stage/initial/drilldown.test
    test/command/suite/select/drilldowns/filter/key.expected
    test/command/suite/select/drilldowns/filter/key.test
    test/command/suite/select/drilldowns/sort_keys/sub_record_column/multiple.expected
    test/command/suite/select/drilldowns/sort_keys/sub_record_column/multiple.test
    test/command/suite/select/filter/geo_in_circle/approximate_type/rect/not_use_index.expected
    test/command/suite/select/function/in_values/with_index/reference/and_optimized.expected
    test/command/suite/select/sort_keys/index/search.expected
    test/command/suite/select/sort_keys/index/search.test
    test/command/suite/sharding/logical_count/cache/columns/initial.expected
    test/command/suite/sharding/logical_count/query_log.expected
    test/command/suite/sharding/logical_range_filter/cache/columns/filtered.expected
    test/command/suite/sharding/logical_range_filter/cache/columns/initial.expected
    test/command/suite/sharding/logical_select/cache/drilldowns/table.expected
    test/command/suite/sharding/logical_select/columns/stage/filtered/filter.expected
    test/command/suite/sharding/logical_select/drilldown/plain/limit/negative.expected
    test/command/suite/sharding/logical_select/drilldown/plain/limit/positive.expected
    test/command/suite/sharding/logical_select/drilldown/plain/offset/negative.expected
    test/command/suite/sharding/logical_select/drilldown/plain/offset/positive.expected
    test/command/suite/sharding/logical_select/drilldown/plain/sort_keys/multiple.expected
    test/command/suite/sharding/logical_select/drilldown/plain/sort_keys/multiple.test
    test/command/suite/sharding/logical_select/drilldowns/calc_types/multiple/all.expected
    test/command/suite/sharding/logical_select/drilldowns/calc_types/multiple/all.test
    test/command/suite/sharding/logical_select/drilldowns/columns/stage/initial/drilldown.expected
    test/command/suite/sharding/logical_select/drilldowns/columns/stage/initial/drilldown.test
    test/command/suite/sharding/logical_select/drilldowns/columns/window_function/window_sum/ascending.expected
    test/command/suite/sharding/logical_select/drilldowns/columns/window_function/window_sum/ascending.test
    test/command/suite/sharding/logical_select/drilldowns/filter/key.expected
    test/command/suite/sharding/logical_select/drilldowns/filter/key.test
    test/command/suite/sharding/logical_select/drilldowns/limit/negative.expected
    test/command/suite/sharding/logical_select/drilldowns/limit/positive.expected
    test/command/suite/sharding/logical_select/drilldowns/offset/negative.expected
    test/command/suite/sharding/logical_select/drilldowns/offset/positive.expected
    test/command/suite/sharding/logical_select/drilldowns/sort_keys/multiple/one_shard.expected
    test/command/suite/sharding/logical_select/drilldowns/sort_keys/multiple/one_shard.test
    test/command/suite/sharding/logical_select/sort_keys/shard_key/ascending.expected
    test/command/suite/sharding/logical_select/sort_keys/shard_key/ascending.test

  Modified: lib/proc/proc_select.c (+63 -31)
===================================================================
--- lib/proc/proc_select.c    2019-05-13 15:48:37 +0900 (1c6170ebc)
+++ lib/proc/proc_select.c    2019-05-13 17:54:59 +0900 (957b82585)
@@ -1366,7 +1366,9 @@ static void
 grn_select_apply_columns(grn_ctx *ctx,
                          grn_select_data *data,
                          grn_obj *table,
-                         grn_hash *columns)
+                         grn_hash *columns,
+                         const char *log_tag_prefix,
+                         const char *query_log_tag_prefix)
 {
   grn_hash_cursor *columns_cursor;
 
@@ -1394,7 +1396,8 @@ grn_select_apply_columns(grn_ctx *ctx,
     if (!column) {
       GRN_PLUGIN_ERROR(ctx,
                        GRN_INVALID_ARGUMENT,
-                       "[select][column][%s][%.*s] failed to create column: %s",
+                       "%s[column][%s][%.*s] failed to create column: %s",
+                       log_tag_prefix,
                        grn_column_stage_name(column_data->stage),
                        (int)(column_data->label.length),
                        column_data->label.value,
@@ -1407,8 +1410,9 @@ grn_select_apply_columns(grn_ctx *ctx,
       grn_obj_close(ctx, column);
       GRN_PLUGIN_ERROR(ctx,
                        GRN_INVALID_ARGUMENT,
-                       "[select][column][%s][%.*s] "
+                       "%s[column][%s][%.*s] "
                        "failed to create expression to compute value: %s",
+                       log_tag_prefix,
                        grn_column_stage_name(column_data->stage),
                        (int)(column_data->label.length),
                        column_data->label.value,
@@ -1428,8 +1432,9 @@ grn_select_apply_columns(grn_ctx *ctx,
       grn_obj_close(ctx, column);
       GRN_PLUGIN_ERROR(ctx,
                        GRN_INVALID_ARGUMENT,
-                       "[select][column][%s][%.*s] "
+                       "%s[column][%s][%.*s] "
                        "failed to parse value: <%.*s>: %s",
+                       log_tag_prefix,
                        grn_column_stage_name(column_data->stage),
                        (int)(column_data->label.length),
                        column_data->label.value,
@@ -1460,8 +1465,9 @@ grn_select_apply_columns(grn_ctx *ctx,
           grn_obj_close(ctx, column);
           GRN_PLUGIN_ERROR(ctx,
                            GRN_INVALID_ARGUMENT,
-                           "[select][column][%s][%.*s] "
+                           "%s[column][%s][%.*s] "
                            "failed to parse sort keys: %s",
+                           log_tag_prefix,
                            grn_column_stage_name(column_data->stage),
                            (int)(column_data->label.length),
                            column_data->label.value,
@@ -1491,8 +1497,9 @@ grn_select_apply_columns(grn_ctx *ctx,
           }
           GRN_PLUGIN_ERROR(ctx,
                            GRN_INVALID_ARGUMENT,
-                           "[select][column][%s][%.*s] "
+                           "%s[column][%s][%.*s] "
                            "failed to parse group keys: %s",
+                           log_tag_prefix,
                            grn_column_stage_name(column_data->stage),
                            (int)(column_data->label.length),
                            column_data->label.value,
@@ -1532,9 +1539,10 @@ grn_select_apply_columns(grn_ctx *ctx,
         grn_obj_close(ctx, column);
         GRN_PLUGIN_ERROR(ctx,
                          GRN_INVALID_ARGUMENT,
-                         "[select][column][%s][%.*s] "
+                         "%s[column][%s][%.*s] "
                          "failed to apply expression to generate column values: "
                          "%s",
+                         log_tag_prefix,
                          grn_column_stage_name(column_data->stage),
                          (int)(column_data->label.length),
                          column_data->label.value,
@@ -1546,7 +1554,8 @@ grn_select_apply_columns(grn_ctx *ctx,
     grn_obj_close(ctx, expression);
 
     GRN_QUERY_LOG(ctx, GRN_QUERY_LOG_SIZE,
-                  ":", "columns[%.*s](%d)",
+                  ":", "%scolumns[%.*s](%d)",
+                  query_log_tag_prefix ? query_log_tag_prefix : "",
                   (int)(column_data->label.length),
                   column_data->label.value,
                   grn_table_size(ctx, table));
@@ -1572,7 +1581,9 @@ grn_select_apply_initial_columns(grn_ctx *ctx,
   grn_select_apply_columns(ctx,
                            data,
                            data->tables.initial,
-                           data->columns.initial);
+                           data->columns.initial,
+                           "[select]",
+                           NULL);
 
   return ctx->rc == GRN_SUCCESS;
 }
@@ -1624,7 +1635,9 @@ grn_select_apply_filtered_columns(grn_ctx *ctx,
   grn_select_apply_columns(ctx,
                            data,
                            data->tables.result,
-                           data->columns.filtered);
+                           data->columns.filtered,
+                           "[select]",
+                           NULL);
 
   return ctx->rc == GRN_SUCCESS;
 }
@@ -1784,9 +1797,8 @@ grn_select_apply_adjuster(grn_ctx *ctx,
   grn_obj_unlink(ctx, adjuster);
 
   GRN_QUERY_LOG(ctx, GRN_QUERY_LOG_SIZE,
-                ":", "%s%sadjust(%d)",
+                ":", "%sadjust(%d)",
                 query_log_tag_prefix ? query_log_tag_prefix : "",
-                query_log_tag_prefix ? "." : "",
                 grn_table_size(ctx, result));
 
   return GRN_TRUE;
@@ -1915,7 +1927,11 @@ grn_select_sort(grn_ctx *ctx,
   grn_table_sort_key_close(ctx, keys, n_keys);
 
   GRN_QUERY_LOG(ctx, GRN_QUERY_LOG_SIZE,
-                ":", "sort(%d)", data->limit);
+                ":",
+                "sort(%d): %.*s",
+                data->limit,
+                (int)(data->sort_keys.length),
+                data->sort_keys.value);
 
   return ctx->rc == GRN_SUCCESS;
 }
@@ -2042,7 +2058,9 @@ grn_select_apply_output_columns(grn_ctx *ctx,
   grn_select_apply_columns(ctx,
                            data,
                            data->tables.sorted,
-                           data->columns.output);
+                           data->columns.output,
+                           "[select]",
+                           NULL);
 
   return ctx->rc == GRN_SUCCESS;
 }
@@ -2314,11 +2332,11 @@ grn_select_drilldown_execute(grn_ctx *ctx,
   GRN_TEXT_PUTC(ctx, &log_tag_prefix, '\0');
   if (data->drilldown.keys.length == 0) {
     grn_text_printf(ctx, &query_log_tag_prefix,
-                    "drilldowns[%.*s]",
+                    "drilldowns[%.*s].",
                     (int)(drilldown->label.length),
                     drilldown->label.value);
   } else {
-    GRN_TEXT_SETS(ctx, &query_log_tag_prefix, "drilldown");
+    GRN_TEXT_SETS(ctx, &query_log_tag_prefix, "drilldown.");
   }
   GRN_TEXT_PUTC(ctx, &query_log_tag_prefix, '\0');
 
@@ -2428,11 +2446,19 @@ grn_select_drilldown_execute(grn_ctx *ctx,
     goto exit;
   }
 
+  GRN_QUERY_LOG(ctx, GRN_QUERY_LOG_SIZE,
+                ":", "%.*s(%u)",
+                (int)(GRN_TEXT_LEN(&query_log_tag_prefix) - 2),
+                GRN_TEXT_VALUE(&query_log_tag_prefix),
+                grn_table_size(ctx, result->table));
+
   if (drilldown->columns.initial) {
     grn_select_apply_columns(ctx,
                              data,
                              result->table,
-                             drilldown->columns.initial);
+                             drilldown->columns.initial,
+                             GRN_TEXT_VALUE(&log_tag_prefix),
+                             GRN_TEXT_VALUE(&query_log_tag_prefix));
   }
 
   if (drilldown->filter.length > 0) {
@@ -2493,6 +2519,11 @@ grn_select_drilldown_execute(grn_ctx *ctx,
       goto exit;
     }
     grn_obj_close(ctx, expression);
+
+    GRN_QUERY_LOG(ctx, GRN_QUERY_LOG_SIZE,
+                  ":", "%sfilter(%u)",
+                  GRN_TEXT_VALUE(&query_log_tag_prefix),
+                  grn_table_size(ctx, drilldown->filtered_result));
   }
 
   {
@@ -2511,20 +2542,6 @@ grn_select_drilldown_execute(grn_ctx *ctx,
                               GRN_TEXT_VALUE(&query_log_tag_prefix));
   }
 
-  {
-    unsigned int n_hits;
-
-    if (drilldown->filtered_result) {
-      n_hits = grn_table_size(ctx, drilldown->filtered_result);
-    } else {
-      n_hits = grn_table_size(ctx, result->table);
-    }
-    GRN_QUERY_LOG(ctx, GRN_QUERY_LOG_SIZE,
-                  ":", "%s(%u)",
-                  GRN_TEXT_VALUE(&query_log_tag_prefix),
-                  n_hits);
-  }
-
 exit :
   GRN_OBJ_FIN(ctx, &log_tag_prefix);
   GRN_OBJ_FIN(ctx, &query_log_tag_prefix);
@@ -2877,6 +2894,21 @@ grn_select_output_drilldowns(grn_ctx *ctx,
         if (sorted) {
           grn_table_sort(ctx, target_table, offset, limit,
                          sorted, sort_keys, n_sort_keys);
+          if (is_labeled) {
+            GRN_QUERY_LOG(ctx, GRN_QUERY_LOG_SIZE,
+                          ":", "drilldowns[%.*s].sort(%d): %.*s",
+                          (int)(drilldown->label.length),
+                          drilldown->label.value,
+                          limit,
+                          (int)(drilldown->sort_keys.length),
+                          drilldown->sort_keys.value);
+          } else {
+            GRN_QUERY_LOG(ctx, GRN_QUERY_LOG_SIZE,
+                          ":", "drilldown.sort(%d): %.*s",
+                          limit,
+                          (int)(drilldown->sort_keys.length),
+                          drilldown->sort_keys.value);
+          }
           data->output.formatter->drilldown_label(ctx, data, drilldown);
           if (!grn_select_output_columns(ctx,
                                          data,

  Modified: plugins/sharding/dynamic_columns.rb (+45 -18)
===================================================================
--- plugins/sharding/dynamic_columns.rb    2019-05-13 15:48:37 +0900 (004c6527e)
+++ plugins/sharding/dynamic_columns.rb    2019-05-13 17:54:59 +0900 (bc3a5a63f)
@@ -4,7 +4,7 @@ module Groonga
       include Enumerable
 
       class << self
-        def parse(input)
+        def parse(tag, input)
           initial_contexts = {}
           filtered_contexts = {}
           output_contexts = {}
@@ -21,7 +21,9 @@ module Groonga
             else
               next
             end
-            contexts[label] = DynamicColumnExecuteContext.new(label, arguments)
+            contexts[label] = DynamicColumnExecuteContext.new(tag,
+                                                              label,
+                                                              arguments)
           end
 
           new(DynamicColumnExecuteContexts.new(initial_contexts),
@@ -125,15 +127,26 @@ module Groonga
         end
 
         if options.fetch(:normal, true)
-          targets.each do |result_set, options|
+          targets.each do |result_set, target_options|
             normal_contexts.each do |context|
-              context.apply(result_set, options)
+              global_options = nil
+              if options and options[:query_log_prefix]
+                global_options = {
+                  query_log_prefix: options[:query_log_prefix],
+                }
+              end
+              if target_options and global_options
+                target_options = global_options.merge(target_options)
+              elsif global_options
+                target_options = global_options
+              end
+              context.apply(result_set, target_options)
             end
           end
         end
         if options.fetch(:window_function, true)
           window_function_contexts.each do |context|
-            context.apply_window_function(targets)
+            context.apply_window_function(targets, options)
           end
         end
       end
@@ -183,6 +196,7 @@ module Groonga
     end
 
     class DynamicColumnExecuteContext
+      include QueryLoggable
       include KeysParsable
 
       attr_reader :label
@@ -192,7 +206,8 @@ module Groonga
       attr_reader :value
       attr_reader :window_sort_keys
       attr_reader :window_group_keys
-      def initialize(label, arguments)
+      def initialize(tag, label, arguments)
+        @tag = tag
         @label = label
         @stage = arguments["stage"]
         @type = parse_type(arguments["type"])
@@ -210,22 +225,29 @@ module Groonga
       def apply(table, options=nil)
         return if table.find_column(@label)
         column = table.create_column(@label, @flags, @type)
-        return if table.empty?
 
-        condition = nil
-        condition = options[:condition] if options
-        expression = Expression.create(table)
-        begin
-          expression.parse(@value)
-          expression.condition = condition if condition
-          table.apply_expression(column, expression)
-        ensure
-          expression.close
+        p options
+        query_log_prefix = nil
+        query_log_prefix = options[:query_log_prefix] if options
+        unless table.empty?
+          condition = nil
+          condition = options[:condition] if options
+          expression = Expression.create(table)
+          begin
+            expression.parse(@value)
+            expression.condition = condition if condition
+            table.apply_expression(column, expression)
+          ensure
+            expression.close
+          end
         end
+        query_logger.log(:size, ":",
+                         "#{query_log_prefix}columns[#{@label}](#{table.size})")
       end
 
-      def apply_window_function(targets)
+      def apply_window_function(targets, options=nil)
         executor = WindowFunctionExecutor.new
+        n_records = 0
         begin
           executor.source = @value
           executor.sort_keys = @window_sort_keys.join(", ")
@@ -240,12 +262,17 @@ module Groonga
               executor.add_context_table(table)
             else
               executor.add_table(table)
+              n_records += table.size
             end
           end
           executor.execute
         ensure
           executor.close
         end
+        query_log_prefix = nil
+        query_log_prefix = options[:query_log_prefix] if options
+        query_logger.log(:size, ":",
+                         "#{query_log_prefix}columns[#{@label}](#{n_records})")
       end
 
       private
@@ -276,7 +303,7 @@ module Groonga
       end
 
       def error_message_tag
-        "[logical_select][columns][#{@stage}][#{@label}]"
+        "#{@tag}[columns][#{@stage}][#{@label}]"
       end
     end
   end

  Modified: plugins/sharding/logical_count.rb (+2 -2)
===================================================================
--- plugins/sharding/logical_count.rb    2019-05-13 15:48:37 +0900 (604d11b8e)
+++ plugins/sharding/logical_count.rb    2019-05-13 17:54:59 +0900 (401ec6f8b)
@@ -50,7 +50,7 @@ module Groonga
         key << "#{input[:max_border]}\0"
         key << "#{input[:filter]}\0"
         key << "#{input[:post_filter]}\0"
-        dynamic_columns = DynamicColumns.parse(input)
+        dynamic_columns = DynamicColumns.parse("[logical_count]", input)
         key << dynamic_columns.cache_key
         key
       end
@@ -74,7 +74,7 @@ module Groonga
         def initialize(input, target_range)
           @filter = input[:filter]
           @post_filter = input[:post_filter]
-          @dynamic_columns = DynamicColumns.parse(input)
+          @dynamic_columns = DynamicColumns.parse("[logical_count]", input)
           @target_range = target_range
           @contexts = []
           @temporary_tables = []

  Modified: plugins/sharding/logical_range_filter.rb (+4 -2)
===================================================================
--- plugins/sharding/logical_range_filter.rb    2019-05-13 15:48:37 +0900 (0b8db30ec)
+++ plugins/sharding/logical_range_filter.rb    2019-05-13 17:54:59 +0900 (eebd74f1e)
@@ -75,7 +75,8 @@ module Groonga
         key << "#{input[:use_range_index]}\0"
         key << "#{input[:post_filter]}\0"
         key << "#{input[:sort_keys]}\0"
-        dynamic_columns = DynamicColumns.parse(input)
+        dynamic_columns = DynamicColumns.parse("[logical_range_filter]",
+                                               input)
         key << dynamic_columns.cache_key
         key
       end
@@ -109,7 +110,8 @@ module Groonga
           @post_filter = @input[:post_filter]
           @sort_keys = parse_keys(@input[:sort_keys])
 
-          @dynamic_columns = DynamicColumns.parse(@input)
+          @dynamic_columns = DynamicColumns.parse("[logical_range_filter]",
+                                                  @input)
 
           @current_offset = @offset
           @current_limit = @limit

  Modified: plugins/sharding/logical_select.rb (+78 -37)
===================================================================
--- plugins/sharding/logical_select.rb    2019-05-13 15:48:37 +0900 (67d215231)
+++ plugins/sharding/logical_select.rb    2019-05-13 17:54:59 +0900 (def5e4a1c)
@@ -109,7 +109,7 @@ module Groonga
           key << "#{drilldown.filter}\0"
           key << drilldown.dynamic_columns.cache_key
         end
-        dynamic_columns = DynamicColumns.parse(input)
+        dynamic_columns = DynamicColumns.parse("[logical_select]", input)
         key << dynamic_columns.cache_key
         key
       end
@@ -200,7 +200,18 @@ module Groonga
           end
           result_sets.each do |result_set|
             if result_set.size > current_offset
-              writer.write_table_records(result_set, output_columns, options)
+              if context.sort_keys.empty?
+                writer.write_table_records(result_set, output_columns, options)
+              else
+                sorted_result_set = result_set.sort(context.sort_keys, options)
+                context.temporary_tables << sorted_result_set
+                message = "sort(#{sorted_result_set.size}): "
+                message << context.sort_keys.join(",")
+                query_logger.log(:size, ":", message)
+                writer.write_table_records(sorted_result_set,
+                                           output_columns,
+                                           offset: 0, limit: -1)
+              end
               n_written = [result_set.size - current_offset, current_limit].min
               current_limit -= n_written
               n_outputs += n_written
@@ -220,23 +231,33 @@ module Groonga
         plain_drilldown = execute_context.plain_drilldown
 
         drilldowns = plain_drilldown.result_sets
+        sort_keys = plain_drilldown.sort_keys
         output_columns = plain_drilldown.output_columns
-        options = {
-          :offset => plain_drilldown.offset,
-          :limit  => plain_drilldown.limit,
-        }
 
         drilldowns.each do |drilldown|
+          options = {
+            :offset => plain_drilldown.offset,
+            :limit  => plain_drilldown.limit,
+          }
+          n_records = drilldown.size
           limit = options[:limit]
-          limit += drilldown.size + 1 if limit < 0
+          limit += n_records + 1 if limit < 0
           offset = options[:offset]
-          offset += drilldown.size if offset < 0
-          n_written = [drilldown.size - offset, limit].min
+          offset += n_records if offset < 0
+          n_written = [n_records - offset, limit].min
           n_elements = 2 # for N hits and columns
           n_elements += n_written
+          unless sort_keys.empty?
+            drilldown = drilldown.sort(sort_keys, options)
+            plain_drilldown.temporary_tables << drilldown
+            message = "drilldown.sort(#{drilldown.size}): "
+            message << sort_keys.join(",")
+            query_logger.log(:size, ":", message)
+            options = {offset: 0, limit: -1}
+          end
           writer.array("RESULTSET", n_elements) do
             writer.array("NHITS", 1) do
-              writer.write(drilldown.size)
+              writer.write(n_records)
             end
             writer.write_table_columns(drilldown, output_columns)
             writer.write_table_records(drilldown, output_columns,
@@ -252,11 +273,14 @@ module Groonga
 
         writer.map("DRILLDOWNS", labeled_drilldowns.n_result_sets) do
           labeled_drilldowns.each do |drilldown|
+            query_log_tag = "drilldowns[#{drilldown.label}]"
+
             writer.write(drilldown.label)
 
             result_set = drilldown.result_set
+            n_records = result_set.size
             n_elements = 2 # for N hits and columns
-            n_elements += result_set.size
+            n_elements += n_records
             output_columns = drilldown.output_columns
             options = {
               :offset => drilldown.offset,
@@ -267,10 +291,20 @@ module Groonga
             limit += result_set.size + 1 if limit < 0
             offset = options[:offset]
             offset += result_set.size if offset < 0
-            n_written = [result_set.size - offset, limit].min
+            if drilldown.sort_keys.empty?
+              n_written = [n_records - offset, limit].min
+            else
+              result_set = result_set.sort(drilldown.sort_keys, options)
+              drilldown.temporary_tables << result_set
+              message = "#{query_log_tag}.sort(#{result_set.size}): "
+              message << drilldown.sort_keys.join(",")
+              query_logger.log(:size, ":", message)
+              options = {offset: 0, limit: -1}
+              n_written = result_set.size
+            end
             writer.array("RESULTSET", n_elements) do
               writer.array("NHITS", 1) do
-                writer.write(result_set.size)
+                writer.write(n_records)
               end
               writer.write_table_columns(result_set, output_columns)
               if is_command_version1 and drilldown.need_command_version2?
@@ -283,7 +317,9 @@ module Groonga
                 writer.write_table_records(result_set, output_columns, options)
               end
             end
-            query_logger.log(:size, ":", "output.drilldowns(#{n_written})")
+            query_logger.log(:size,
+                             ":",
+                             "output.#{query_log_tag}(#{n_written})")
           end
         end
       end
@@ -359,7 +395,7 @@ module Groonga
           @load_columns = @input[:load_columns]
           @load_values = @input[:load_values]
 
-          @dynamic_columns = DynamicColumns.parse(@input)
+          @dynamic_columns = DynamicColumns.parse("[logical_select]", @input)
 
           @result_sets = []
           @shard_targets = []
@@ -536,7 +572,8 @@ module Groonga
           @filter = parameters["filter"]
           @table = parameters["table"]
 
-          @dynamic_columns = DynamicColumns.parse(parameters)
+          tag = "[logical_select][drilldowns][#{@label}]"
+          @dynamic_columns = DynamicColumns.parse(tag, parameters)
 
           @result_set = nil
 
@@ -579,6 +616,8 @@ module Groonga
       end
 
       class Executor
+        include QueryLoggable
+
         def initialize(context)
           @context = context
         end
@@ -642,6 +681,7 @@ module Groonga
 
         def execute_plain_drilldown
           drilldown =****@conte*****_drilldown
+          query_log_prefix = "drilldown"
           group_result = TableGroupResult.new
           begin
             group_result.key_begin = 0
@@ -656,15 +696,15 @@ module Groonga
                 end
               end
               result_set = group_result.table
-              result_set = apply_drilldown_filter(drilldown, result_set)
+              query_logger.log(:size,
+                               ":",
+                               "#{query_log_prefix}(#{result_set.size})")
+              result_set = apply_drilldown_filter(query_log_prefix,
+                                                  drilldown,
+                                                  result_set)
               drilldown.temporary_tables << result_set
               group_result.table = nil
-              unless drilldown.sort_keys.empty?
-                result_set = result_set.sort(drilldown.sort_keys)
-                drilldown.temporary_tables << result_set
-              end
               drilldown.result_sets << result_set
-              group_result.table = nil
             end
           ensure
             group_result.close
@@ -675,6 +715,7 @@ module Groonga
           drilldowns =****@conte*****_drilldowns
 
           drilldowns.tsort_each do |drilldown|
+            query_log_prefix = "drilldowns[#{drilldown.label}]"
             group_result = TableGroupResult.new
             keys = drilldown.keys
             begin
@@ -700,14 +741,17 @@ module Groonga
                 end
               end
               result_set = group_result.table
-              drilldown.dynamic_columns.apply_initial([[result_set]])
-              result_set = apply_drilldown_filter(drilldown, result_set)
+              query_logger.log(:size,
+                               ":",
+                               "#{query_log_prefix}(#{result_set.size})")
+              options = {query_log_prefix: "#{query_log_prefix}."}
+              drilldown.dynamic_columns.apply_initial([[result_set]],
+                                                      options)
+              result_set = apply_drilldown_filter(query_log_prefix,
+                                                  drilldown,
+                                                  result_set)
               drilldown.temporary_tables << result_set
               group_result.table = nil
-              unless drilldown.sort_keys.empty?
-                result_set = result_set.sort(drilldown.sort_keys)
-                drilldown.temporary_tables << result_set
-              end
               drilldown.result_set = result_set
             ensure
               group_result.close
@@ -725,7 +769,7 @@ module Groonga
           end
         end
 
-        def apply_drilldown_filter(drilldown, result_set)
+        def apply_drilldown_filter(query_log_prefix, drilldown, result_set)
           filter = drilldown.filter
           return result_set if filter.nil?
 
@@ -734,6 +778,10 @@ module Groonga
           expression.parse(filter)
           filtered_result_set = result_set.select(expression)
           drilldown.temporary_tables << result_set
+          n_records = filtered_result_set.size
+          query_logger.log(:size,
+                           ":",
+                           "#{query_log_prefix}.filter(#{n_records})")
           filtered_result_set
         end
       end
@@ -818,14 +866,7 @@ module Groonga
             result_set = apply_post_filter(result_set)
             @temporary_tables << result_set
           end
-
-          if @sort_keys.empty?
-            @result_sets << result_set
-          else
-            sorted_result_set = result_set.sort(@sort_keys)
-            @temporary_tables << sorted_result_set
-            @result_sets << sorted_result_set
-          end
+          @result_sets << result_set
         end
 
         private

  Modified: test/command/suite/select/drilldown/plain/adjuster/filter.expected (+2 -1)
===================================================================
--- test/command/suite/select/drilldown/plain/adjuster/filter.expected    2019-05-13 15:48:37 +0900 (32f6511ff)
+++ test/command/suite/select/drilldown/plain/adjuster/filter.expected    2019-05-13 17:54:59 +0900 (8805f781c)
@@ -80,9 +80,10 @@ select Memos   --limit 0   --output_columns _id   --drilldown tags   --drilldown
 ]
 #>select --drilldown "tags" --drilldown_adjuster "categories @ \"full-text-search\" * 2 + categories @ \"mysql\"" --drilldown_filter "_key == \"groonga\"" --drilldown_output_columns "_key,_nsubrecs,_score" --limit "0" --output_columns "_id" --table "Memos"
 #:000000000000000 select(3)
+#:000000000000000 drilldown(3)
 #:000000000000000 filter(1): #<accessor _key(anonymous)._key(Tags)> equal "groonga"
+#:000000000000000 drilldown.filter(1)
 #:000000000000000 drilldown.adjust(1)
-#:000000000000000 drilldown(1)
 #:000000000000000 output(0)
 #:000000000000000 output.drilldown(1)
 #<000000000000000 rc=0

  Modified: test/command/suite/select/drilldown/plain/adjuster/no_filter.expected (+1 -1)
===================================================================
--- test/command/suite/select/drilldown/plain/adjuster/no_filter.expected    2019-05-13 15:48:37 +0900 (666c05906)
+++ test/command/suite/select/drilldown/plain/adjuster/no_filter.expected    2019-05-13 17:54:59 +0900 (9a8fc5b66)
@@ -90,8 +90,8 @@ select Memos   --limit 0   --output_columns _id   --drilldown tags   --drilldown
 ]
 #>select --drilldown "tags" --drilldown_adjuster "categories @ \"full-text-search\" * 2 + categories @ \"mysql\"" --drilldown_output_columns "_key,_nsubrecs,_score" --limit "0" --output_columns "_id" --table "Memos"
 #:000000000000000 select(3)
-#:000000000000000 drilldown.adjust(3)
 #:000000000000000 drilldown(3)
+#:000000000000000 drilldown.adjust(3)
 #:000000000000000 output(0)
 #:000000000000000 output.drilldown(3)
 #<000000000000000 rc=0

  Modified: test/command/suite/select/drilldown/plain/sort_keys.expected (+7 -0)
===================================================================
--- test/command/suite/select/drilldown/plain/sort_keys.expected    2019-05-13 15:48:37 +0900 (a14956c0f)
+++ test/command/suite/select/drilldown/plain/sort_keys.expected    2019-05-13 17:54:59 +0900 (e255912cf)
@@ -59,3 +59,10 @@ select Memos   --limit 0   --output_columns _id   --drilldown tags   --drilldown
     ]
   ]
 ]
+#>select --drilldown "tags" --drilldown_output_columns "_key,_nsubrecs" --drilldown_sort_keys "-_nsubrecs,_key" --limit "0" --output_columns "_id" --table "Memos"
+#:000000000000000 select(5)
+#:000000000000000 drilldown(3)
+#:000000000000000 output(0)
+#:000000000000000 drilldown.sort(3): -_nsubrecs,_key
+#:000000000000000 output.drilldown(3)
+#<000000000000000 rc=0

  Modified: test/command/suite/select/drilldown/plain/sort_keys.test (+2 -0)
===================================================================
--- test/command/suite/select/drilldown/plain/sort_keys.test    2019-05-13 15:48:37 +0900 (f15788ab1)
+++ test/command/suite/select/drilldown/plain/sort_keys.test    2019-05-13 17:54:59 +0900 (9a7149605)
@@ -10,9 +10,11 @@ load --table Memos
 {"_key": "Groonga is good!", "tags": ["Groonga"]}
 ]
 
+#@collect-query-log true
 select Memos \
   --limit 0 \
   --output_columns _id \
   --drilldown tags \
   --drilldown_output_columns _key,_nsubrecs \
   --drilldown_sort_keys -_nsubrecs,_key
+#@collect-query-log false

  Modified: test/command/suite/select/drilldowns/adjuster/filter.expected (+2 -1)
===================================================================
--- test/command/suite/select/drilldowns/adjuster/filter.expected    2019-05-13 15:48:37 +0900 (3a4273109)
+++ test/command/suite/select/drilldowns/adjuster/filter.expected    2019-05-13 17:54:59 +0900 (3f8ae86b9)
@@ -82,9 +82,10 @@ select Memos   --limit 0   --output_columns _id   --drilldowns[groonga_tag].keys
 ]
 #>select --drilldowns[groonga_tag].adjuster "categories @ \"full-text-search\" * 2 + categories @ \"mysql\"" --drilldowns[groonga_tag].filter "_key == \"groonga\"" --drilldowns[groonga_tag].keys "tags" --drilldowns[groonga_tag].output_columns "_key,_nsubrecs,_score" --limit "0" --output_columns "_id" --table "Memos"
 #:000000000000000 select(3)
+#:000000000000000 drilldowns[groonga_tag](3)
 #:000000000000000 filter(1): #<accessor _key(anonymous)._key(Tags)> equal "groonga"
+#:000000000000000 drilldowns[groonga_tag].filter(1)
 #:000000000000000 drilldowns[groonga_tag].adjust(1)
-#:000000000000000 drilldowns[groonga_tag](1)
 #:000000000000000 output(0)
 #:000000000000000 output.drilldowns[groonga_tag](1)
 #<000000000000000 rc=0

  Modified: test/command/suite/select/drilldowns/adjuster/no_filter.expected (+1 -1)
===================================================================
--- test/command/suite/select/drilldowns/adjuster/no_filter.expected    2019-05-13 15:48:37 +0900 (79eee87d2)
+++ test/command/suite/select/drilldowns/adjuster/no_filter.expected    2019-05-13 17:54:59 +0900 (bc3042964)
@@ -92,8 +92,8 @@ select Memos   --limit 0   --output_columns _id   --drilldowns[tags].keys tags
 ]
 #>select --drilldowns[tags].adjuster "categories @ \"full-text-search\" * 2 + categories @ \"mysql\"" --drilldowns[tags].keys "tags" --drilldowns[tags].output_columns "_key,_nsubrecs,_score" --limit "0" --output_columns "_id" --table "Memos"
 #:000000000000000 select(3)
-#:000000000000000 drilldowns[tags].adjust(3)
 #:000000000000000 drilldowns[tags](3)
+#:000000000000000 drilldowns[tags].adjust(3)
 #:000000000000000 output(0)
 #:000000000000000 output.drilldowns[tags](3)
 #<000000000000000 rc=0

  Modified: test/command/suite/select/drilldowns/columns/stage/initial/drilldown.expected (+10 -0)
===================================================================
--- test/command/suite/select/drilldowns/columns/stage/initial/drilldown.expected    2019-05-13 15:48:37 +0900 (ea092dbb9)
+++ test/command/suite/select/drilldowns/columns/stage/initial/drilldown.expected    2019-05-13 17:54:59 +0900 (9e3bf04c4)
@@ -169,3 +169,13 @@ select Shops   --drilldowns[item].keys items   --drilldowns[item].sortby price
     }
   ]
 ]
+#>select --drilldowns[item].columns[price_with_tax].flags "COLUMN_SCALAR" --drilldowns[item].columns[price_with_tax].stage "initial" --drilldowns[item].columns[price_with_tax].type "UInt32" --drilldowns[item].columns[price_with_tax].value "price * 1.08" --drilldowns[item].keys "items" --drilldowns[item].output_columns "_key,_nsubrecs,price,price_with_tax" --drilldowns[item].sortby "price" --drilldowns[real_price].keys "price_with_tax" --drilldowns[real_price].table "item" --table "Shops"
+#:000000000000000 select(3)
+#:000000000000000 drilldowns[item](6)
+#:000000000000000 drilldowns[item].columns[price_with_tax](6)
+#:000000000000000 drilldowns[real_price](3)
+#:000000000000000 output(3)
+#:000000000000000 drilldowns[item].sort(6): price
+#:000000000000000 output.drilldowns[item](6)
+#:000000000000000 output.drilldowns[real_price](3)
+#<000000000000000 rc=0

  Modified: test/command/suite/select/drilldowns/columns/stage/initial/drilldown.test (+2 -0)
===================================================================
--- test/command/suite/select/drilldowns/columns/stage/initial/drilldown.test    2019-05-13 15:48:37 +0900 (b783d4f6c)
+++ test/command/suite/select/drilldowns/columns/stage/initial/drilldown.test    2019-05-13 17:54:59 +0900 (7014d978a)
@@ -21,6 +21,7 @@ load --table Items
 {"_key": "Drink", "price": 300}
 ]
 
+#@collect-query-log true
 select Shops \
   --drilldowns[item].keys items \
   --drilldowns[item].sortby price \
@@ -31,3 +32,4 @@ select Shops \
   --drilldowns[item].columns[price_with_tax].value 'price * 1.08' \
   --drilldowns[real_price].table item \
   --drilldowns[real_price].keys price_with_tax
+#@collect-query-log false

  Modified: test/command/suite/select/drilldowns/filter/key.expected (+8 -0)
===================================================================
--- test/command/suite/select/drilldowns/filter/key.expected    2019-05-13 15:48:37 +0900 (7983ddfbc)
+++ test/command/suite/select/drilldowns/filter/key.expected    2019-05-13 17:54:59 +0900 (019eaf4de)
@@ -86,3 +86,11 @@ select Memos   --drilldowns[tag].keys tag   --drilldowns[tag].filter '_key != "G
     }
   ]
 ]
+#>select --drilldowns[tag].filter "_key != \"Groonga\"" --drilldowns[tag].keys "tag" --table "Memos"
+#:000000000000000 select(4)
+#:000000000000000 drilldowns[tag](3)
+#:000000000000000 filter(2): #<accessor _key(anonymous)._key(Tags)> not_equal "Groonga"
+#:000000000000000 drilldowns[tag].filter(2)
+#:000000000000000 output(4)
+#:000000000000000 output.drilldowns[tag](2)
+#<000000000000000 rc=0

  Modified: test/command/suite/select/drilldowns/filter/key.test (+2 -0)
===================================================================
--- test/command/suite/select/drilldowns/filter/key.test    2019-05-13 15:48:37 +0900 (2cb894c5f)
+++ test/command/suite/select/drilldowns/filter/key.test    2019-05-13 17:54:59 +0900 (04d8ff343)
@@ -11,6 +11,8 @@ load --table Memos
 {"_key": "Rroonga is fast!", "tag": "Rroonga"}
 ]
 
+#@collect-query-log true
 select Memos \
   --drilldowns[tag].keys tag \
   --drilldowns[tag].filter '_key != "Groonga"'
+#@collect-query-log false

  Modified: test/command/suite/select/drilldowns/sort_keys/sub_record_column/multiple.expected (+8 -0)
===================================================================
--- test/command/suite/select/drilldowns/sort_keys/sub_record_column/multiple.expected    2019-05-13 15:48:37 +0900 (8087622aa)
+++ test/command/suite/select/drilldowns/sort_keys/sub_record_column/multiple.expected    2019-05-13 17:54:59 +0900 (e870305a9)
@@ -119,3 +119,11 @@ select Memos   --filter true   --drilldowns[tag].keys tag,date   --drilldowns[ta
     }
   ]
 ]
+#>select --drilldowns[tag].keys "tag,date" --drilldowns[tag].output_columns "_key[0],_key[1],_nsubrecs" --drilldowns[tag].sort_keys "_value.tag._key,_value.date" --filter "true" --table "Memos"
+#:000000000000000 filter(5): true
+#:000000000000000 select(5)
+#:000000000000000 drilldowns[tag](4)
+#:000000000000000 output(5)
+#:000000000000000 drilldowns[tag].sort(4): _value.tag._key,_value.date
+#:000000000000000 output.drilldowns[tag](4)
+#<000000000000000 rc=0

  Modified: test/command/suite/select/drilldowns/sort_keys/sub_record_column/multiple.test (+2 -0)
===================================================================
--- test/command/suite/select/drilldowns/sort_keys/sub_record_column/multiple.test    2019-05-13 15:48:37 +0900 (f47d94a65)
+++ test/command/suite/select/drilldowns/sort_keys/sub_record_column/multiple.test    2019-05-13 17:54:59 +0900 (2236212d8)
@@ -13,8 +13,10 @@ load --table Memos
 {"_key": "Groonga is good!", "tag": "Groonga", "date": "2014-11-17 00:00:00"}
 ]
 
+#@collect-query-log true
 select Memos \
   --filter true \
   --drilldowns[tag].keys tag,date \
   --drilldowns[tag].output_columns _key[0],_key[1],_nsubrecs \
   --drilldowns[tag].sort_keys _value.tag._key,_value.date
+#@collect-query-log false

  Modified: test/command/suite/select/filter/geo_in_circle/approximate_type/rect/not_use_index.expected (+1 -1)
===================================================================
--- test/command/suite/select/filter/geo_in_circle/approximate_type/rect/not_use_index.expected    2019-05-13 15:48:37 +0900 (596c76281)
+++ test/command/suite/select/filter/geo_in_circle/approximate_type/rect/not_use_index.expected    2019-05-13 17:54:59 +0900 (d39a37e6d)
@@ -66,6 +66,6 @@ select Shops --sortby '+_score, +name'   --output_columns 'name, _score, locatio
 #:000000000000000 filter(7): greater(geo_in_circle(Shops.location, "128429532x503148672", 3000, "rect"), 0)
 #:000000000000000 select(7)
 #:000000000000000 score(7)
-#:000000000000000 sort(7)
+#:000000000000000 sort(7): +_score, +name
 #:000000000000000 output(7)
 #<000000000000000 rc=0

  Modified: test/command/suite/select/function/in_values/with_index/reference/and_optimized.expected (+1 -1)
===================================================================
--- test/command/suite/select/function/in_values/with_index/reference/and_optimized.expected    2019-05-13 15:48:37 +0900 (2d58c024f)
+++ test/command/suite/select/function/in_values/with_index/reference/and_optimized.expected    2019-05-13 17:54:59 +0900 (e3f12cebe)
@@ -62,6 +62,6 @@ select Memos   --output_columns _key,tag   --filter 'all_records() && (tag == "g
 #:000000000000000 filter(4): in_values(Memos.tag, #<record:pat:Tags id:1 key:"groonga">, #<record:pat:Tags id:2 key:"mroonga">, #<record:pat:Tags id:4 key:"droonga">)
 #:000000000000000 filter(4): all_records()
 #:000000000000000 select(4)
-#:000000000000000 sort(4)
+#:000000000000000 sort(4): _id
 #:000000000000000 output(4)
 #<000000000000000 rc=0

  Modified: test/command/suite/select/sort_keys/index/search.expected (+6 -0)
===================================================================
--- test/command/suite/select/sort_keys/index/search.expected    2019-05-13 15:48:37 +0900 (d47e4f943)
+++ test/command/suite/select/sort_keys/index/search.expected    2019-05-13 17:54:59 +0900 (d1911d775)
@@ -93,3 +93,9 @@ select Terms --filter true --sort_keys -index
     ]
   ]
 ]
+#>select --filter "true" --sort_keys "-index" --table "Terms"
+#:000000000000000 filter(11): true
+#:000000000000000 select(11)
+#:000000000000000 sort(10): -index
+#:000000000000000 output(10)
+#<000000000000000 rc=0

  Modified: test/command/suite/select/sort_keys/index/search.test (+2 -0)
===================================================================
--- test/command/suite/select/sort_keys/index/search.test    2019-05-13 15:48:37 +0900 (b74d09115)
+++ test/command/suite/select/sort_keys/index/search.test    2019-05-13 17:54:59 +0900 (ee923ddc8)
@@ -14,4 +14,6 @@ load --table Logs
 ["Error: invalid argument."]
 ]
 
+#@collect-query-log true
 select Terms --filter true --sort_keys -index
+#@collect-query-log false

  Modified: test/command/suite/sharding/logical_count/cache/columns/initial.expected (+1 -0)
===================================================================
--- test/command/suite/sharding/logical_count/cache/columns/initial.expected    2019-05-13 15:48:37 +0900 (46f3d778e)
+++ test/command/suite/sharding/logical_count/cache/columns/initial.expected    2019-05-13 17:54:59 +0900 (7e89cf5c1)
@@ -17,6 +17,7 @@ logical_count Logs   --shard_key timestamp   --columns[price_with_tax].stage ini
 [[0,0.0,0.0],2]
 #>logical_count --columns[price_with_tax].flags "COLUMN_SCALAR" --columns[price_with_tax].stage "initial" --columns[price_with_tax].type "UInt32" --columns[price_with_tax].value "price * 1.08" --filter "price_with_tax > 550" --logical_table "Logs" --shard_key "timestamp"
 #:000000000000000 filter(3): true
+#:000000000000000 columns[price_with_tax](3)
 #:000000000000000 filter(2): 2147483650.price_with_tax greater 550
 #:000000000000000 count(2)
 #<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_count/query_log.expected (+1 -0)
===================================================================
--- test/command/suite/sharding/logical_count/query_log.expected    2019-05-13 15:48:37 +0900 (4bc215e79)
+++ test/command/suite/sharding/logical_count/query_log.expected    2019-05-13 17:54:59 +0900 (c3f50da6b)
@@ -17,6 +17,7 @@ logical_count Logs   --shard_key timestamp   --columns[price_with_tax].stage ini
 [[0,0.0,0.0],2]
 #>logical_count --columns[price_with_tax].flags "COLUMN_SCALAR" --columns[price_with_tax].stage "initial" --columns[price_with_tax].type "UInt32" --columns[price_with_tax].value "price * 1.08" --filter "price_with_tax > 550" --logical_table "Logs" --shard_key "timestamp"
 #:000000000000000 filter(3): true
+#:000000000000000 columns[price_with_tax](3)
 #:000000000000000 filter(2): 2147483650.price_with_tax greater 550
 #:000000000000000 count(2)
 #<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_range_filter/cache/columns/filtered.expected (+1 -0)
===================================================================
--- test/command/suite/sharding/logical_range_filter/cache/columns/filtered.expected    2019-05-13 15:48:37 +0900 (f53d13bf0)
+++ test/command/suite/sharding/logical_range_filter/cache/columns/filtered.expected    2019-05-13 17:54:59 +0900 (1061b9ce1)
@@ -43,6 +43,7 @@ logical_range_filter Logs   --shard_key timestamp   --filter '_id > 1'   --colum
 ]
 #>logical_range_filter --columns[price_with_tax].flags "COLUMN_SCALAR" --columns[price_with_tax].stage "filtered" --columns[price_with_tax].type "UInt32" --columns[price_with_tax].value "price * 1.08" --filter "_id > 1" --logical_table "Logs" --output_columns "price,price_with_tax" --shard_key "timestamp"
 #:000000000000000 filter(2): #<accessor _id(Logs_20170315)> greater 1
+#:000000000000000 columns[price_with_tax](2)
 #<000000000000000 rc=0
 logical_range_filter Logs   --shard_key timestamp   --filter '_id > 1'   --columns[price_with_tax].stage filtered   --columns[price_with_tax].type UInt32   --columns[price_with_tax].flags COLUMN_SCALAR   --columns[price_with_tax].value 'price * 1.08'   --output_columns price,price_with_tax
 [

  Modified: test/command/suite/sharding/logical_range_filter/cache/columns/initial.expected (+1 -0)
===================================================================
--- test/command/suite/sharding/logical_range_filter/cache/columns/initial.expected    2019-05-13 15:48:37 +0900 (a1acdc42b)
+++ test/command/suite/sharding/logical_range_filter/cache/columns/initial.expected    2019-05-13 17:54:59 +0900 (18c111f1e)
@@ -47,6 +47,7 @@ logical_range_filter Logs   --shard_key timestamp   --columns[price_with_tax].st
 ]
 #>logical_range_filter --columns[price_with_tax].flags "COLUMN_SCALAR" --columns[price_with_tax].stage "initial" --columns[price_with_tax].type "UInt32" --columns[price_with_tax].value "price * 1.08" --logical_table "Logs" --output_columns "price,price_with_tax" --shard_key "timestamp"
 #:000000000000000 filter(3): true
+#:000000000000000 columns[price_with_tax](3)
 #<000000000000000 rc=0
 logical_range_filter Logs   --shard_key timestamp   --columns[price_with_tax].stage initial   --columns[price_with_tax].type UInt32   --columns[price_with_tax].flags COLUMN_SCALAR   --columns[price_with_tax].value 'price * 1.08'   --output_columns price,price_with_tax
 [

  Modified: test/command/suite/sharding/logical_select/cache/drilldowns/table.expected (+16 -6)
===================================================================
--- test/command/suite/sharding/logical_select/cache/drilldowns/table.expected    2019-05-13 15:48:37 +0900 (7a8372b24)
+++ test/command/suite/sharding/logical_select/cache/drilldowns/table.expected    2019-05-13 17:54:59 +0900 (feee81cdd)
@@ -158,12 +158,17 @@ logical_select Logs   --shard_key timestamp   --limit 0   --output_columns _id
 #:000000000000000 select(2)[Logs_20150203]
 #:000000000000000 select(3)[Logs_20150204]
 #:000000000000000 select(4)[Logs_20150205]
+#:000000000000000 drilldowns[restart](3)
 #:000000000000000 filter(1): #<accessor _key(anonymous)> match "Restart"
+#:000000000000000 drilldowns[restart].filter(1)
+#:000000000000000 drilldowns[action](1)
+#:000000000000000 drilldowns[start](3)
 #:000000000000000 filter(2): #<accessor _key(anonymous)> match "Start"
+#:000000000000000 drilldowns[start].filter(2)
 #:000000000000000 output(0)
-#:000000000000000 output.drilldowns(1)
-#:000000000000000 output.drilldowns(1)
-#:000000000000000 output.drilldowns(2)
+#:000000000000000 output.drilldowns[action](1)
+#:000000000000000 output.drilldowns[restart](1)
+#:000000000000000 output.drilldowns[start](2)
 #<000000000000000 rc=0
 logical_select Logs   --shard_key timestamp   --limit 0   --output_columns _id   --drilldowns[action].table start   --drilldowns[action].keys _key   --drilldowns[restart].stage initial   --drilldowns[restart].keys 'action'   --drilldowns[restart].filter "_key @ 'Restart'"   --drilldowns[restart].output_columns _key   --drilldowns[start].stage initial   --drilldowns[start].keys 'action'   --drilldowns[start].filter "_key @ 'Start'"   --drilldowns[start].output_columns _key
 [
@@ -246,10 +251,15 @@ logical_select Logs   --shard_key timestamp   --limit 0   --output_columns _id
 #:000000000000000 select(2)[Logs_20150203]
 #:000000000000000 select(3)[Logs_20150204]
 #:000000000000000 select(4)[Logs_20150205]
+#:000000000000000 drilldowns[start](3)
 #:000000000000000 filter(2): #<accessor _key(anonymous)> match "Start"
+#:000000000000000 drilldowns[start].filter(2)
+#:000000000000000 drilldowns[action](2)
+#:000000000000000 drilldowns[restart](3)
 #:000000000000000 filter(1): #<accessor _key(anonymous)> match "Restart"
+#:000000000000000 drilldowns[restart].filter(1)
 #:000000000000000 output(0)
-#:000000000000000 output.drilldowns(2)
-#:000000000000000 output.drilldowns(1)
-#:000000000000000 output.drilldowns(2)
+#:000000000000000 output.drilldowns[action](2)
+#:000000000000000 output.drilldowns[restart](1)
+#:000000000000000 output.drilldowns[start](2)
 #<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/columns/stage/filtered/filter.expected (+3 -0)
===================================================================
--- test/command/suite/sharding/logical_select/columns/stage/filtered/filter.expected    2019-05-13 15:48:37 +0900 (c8e0672fb)
+++ test/command/suite/sharding/logical_select/columns/stage/filtered/filter.expected    2019-05-13 17:54:59 +0900 (20fd51859)
@@ -97,5 +97,8 @@ logical_select Logs   --shard_key timestamp   --columns[filtered_id].stage filte
 #:000000000000000 select(2)[Logs_20170316]
 #:000000000000000 filter(2): Logs_20170317.price less 910
 #:000000000000000 select(2)[Logs_20170317]
+#:000000000000000 columns[filtered_id](1)
+#:000000000000000 columns[filtered_id](2)
+#:000000000000000 columns[filtered_id](2)
 #:000000000000000 output(5)
 #<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldown/plain/limit/negative.expected (+1 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldown/plain/limit/negative.expected    2019-05-13 15:48:37 +0900 (692cae743)
+++ test/command/suite/sharding/logical_select/drilldown/plain/limit/negative.expected    2019-05-13 17:54:59 +0900 (a7c7960a2)
@@ -141,6 +141,7 @@ logical_select Logs timestamp   --limit 0   --drilldown action   --drilldown_lim
 #:000000000000000 select(2)[Logs_20150203]
 #:000000000000000 select(3)[Logs_20150204]
 #:000000000000000 select(4)[Logs_20150205]
+#:000000000000000 drilldown(3)
 #:000000000000000 output(0)
 #:000000000000000 output.drilldown(2)
 #<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldown/plain/limit/positive.expected (+1 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldown/plain/limit/positive.expected    2019-05-13 15:48:37 +0900 (bc32017cd)
+++ test/command/suite/sharding/logical_select/drilldown/plain/limit/positive.expected    2019-05-13 17:54:59 +0900 (3e76de9d1)
@@ -137,6 +137,7 @@ logical_select Logs timestamp   --limit 0   --drilldown action   --drilldown_lim
 #:000000000000000 select(2)[Logs_20150203]
 #:000000000000000 select(3)[Logs_20150204]
 #:000000000000000 select(4)[Logs_20150205]
+#:000000000000000 drilldown(3)
 #:000000000000000 output(0)
 #:000000000000000 output.drilldown(1)
 #<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldown/plain/offset/negative.expected (+1 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldown/plain/offset/negative.expected    2019-05-13 15:48:37 +0900 (7912f744c)
+++ test/command/suite/sharding/logical_select/drilldown/plain/offset/negative.expected    2019-05-13 17:54:59 +0900 (3a2778e7d)
@@ -137,6 +137,7 @@ logical_select Logs timestamp   --limit 0   --drilldown action   --drilldown_off
 #:000000000000000 select(2)[Logs_20150203]
 #:000000000000000 select(3)[Logs_20150204]
 #:000000000000000 select(4)[Logs_20150205]
+#:000000000000000 drilldown(3)
 #:000000000000000 output(0)
 #:000000000000000 output.drilldown(1)
 #<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldown/plain/offset/positive.expected (+1 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldown/plain/offset/positive.expected    2019-05-13 15:48:37 +0900 (4e7dc88d0)
+++ test/command/suite/sharding/logical_select/drilldown/plain/offset/positive.expected    2019-05-13 17:54:59 +0900 (e855ec0eb)
@@ -141,6 +141,7 @@ logical_select Logs timestamp   --limit 0   --drilldown action   --drilldown_off
 #:000000000000000 select(2)[Logs_20150203]
 #:000000000000000 select(3)[Logs_20150204]
 #:000000000000000 select(4)[Logs_20150205]
+#:000000000000000 drilldown(3)
 #:000000000000000 output(0)
 #:000000000000000 output.drilldown(2)
 #<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldown/plain/sort_keys/multiple.expected (+9 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldown/plain/sort_keys/multiple.expected    2019-05-13 15:48:37 +0900 (dd26a3d58)
+++ test/command/suite/sharding/logical_select/drilldown/plain/sort_keys/multiple.expected    2019-05-13 17:54:59 +0900 (10efa784b)
@@ -141,3 +141,12 @@ logical_select Logs timestamp   --limit 0   --drilldown action   --drilldown_sor
     ]
   ]
 ]
+#>logical_select --drilldown "action" --drilldown_sort_keys "-_nsubrecs,_key" --limit "0" --logical_table "Logs" --shard_key "timestamp"
+#:000000000000000 select(2)[Logs_20150203]
+#:000000000000000 select(3)[Logs_20150204]
+#:000000000000000 select(4)[Logs_20150205]
+#:000000000000000 drilldown(3)
+#:000000000000000 output(0)
+#:000000000000000 drilldown.sort(3): -_nsubrecs,_key
+#:000000000000000 output.drilldown(3)
+#<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldown/plain/sort_keys/multiple.test (+2 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldown/plain/sort_keys/multiple.test    2019-05-13 15:48:37 +0900 (5e41daf00)
+++ test/command/suite/sharding/logical_select/drilldown/plain/sort_keys/multiple.test    2019-05-13 17:54:59 +0900 (d99641fd5)
@@ -74,7 +74,9 @@ load --table Logs_20150205
 }
 ]
 
+#@collect-query-log true
 logical_select Logs timestamp \
   --limit 0 \
   --drilldown action \
   --drilldown_sort_keys -_nsubrecs,_key
+#@collect-query-log false

  Modified: test/command/suite/sharding/logical_select/drilldowns/calc_types/multiple/all.expected (+7 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/calc_types/multiple/all.expected    2019-05-13 15:48:37 +0900 (3fa5eefcb)
+++ test/command/suite/sharding/logical_select/drilldowns/calc_types/multiple/all.expected    2019-05-13 17:54:59 +0900 (c73bfbd6f)
@@ -160,3 +160,10 @@ logical_select Memos   --shard_key created_at   --limit 0   --drilldowns[tag].ke
     }
   ]
 ]
+#>logical_select --drilldowns[tag].calc_target "priority" --drilldowns[tag].calc_types "AVG, MAX, MIN, SUM" --drilldowns[tag].keys "tag,user" --drilldowns[tag].output_columns "_value.tag,_value.user,_max,_min,_sum,_avg" --limit "0" --logical_table "Memos" --shard_key "created_at"
+#:000000000000000 select(4)[Memos_20150709]
+#:000000000000000 select(8)[Memos_20150710]
+#:000000000000000 drilldowns[tag](4)
+#:000000000000000 output(0)
+#:000000000000000 output.drilldowns[tag](4)
+#<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldowns/calc_types/multiple/all.test (+2 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/calc_types/multiple/all.test    2019-05-13 15:48:37 +0900 (274966381)
+++ test/command/suite/sharding/logical_select/drilldowns/calc_types/multiple/all.test    2019-05-13 17:54:59 +0900 (27a944c97)
@@ -48,6 +48,7 @@ load --table Memos_20150710
  "created_at": "2015/07/10 07:00:00"}
 ]
 
+#@collect-query-log true
 logical_select Memos \
   --shard_key created_at \
   --limit 0 \
@@ -55,3 +56,4 @@ logical_select Memos \
   --drilldowns[tag].calc_types 'AVG, MAX, MIN, SUM' \
   --drilldowns[tag].calc_target priority \
   --drilldowns[tag].output_columns _value.tag,_value.user,_max,_min,_sum,_avg
+#@collect-query-log false

  Modified: test/command/suite/sharding/logical_select/drilldowns/columns/stage/initial/drilldown.expected (+16 -4)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/columns/stage/initial/drilldown.expected    2019-05-13 15:48:37 +0900 (897dcf757)
+++ test/command/suite/sharding/logical_select/drilldowns/columns/stage/initial/drilldown.expected    2019-05-13 17:54:59 +0900 (b379bd284)
@@ -144,18 +144,30 @@ logical_select Logs   --shard_key timestamp   --output_columns _id   --limit 0
           ]
         ],
         [
-          324,
-          1
+          1080,
+          2
         ],
         [
           540,
           3
         ],
         [
-          1080,
-          2
+          324,
+          1
         ]
       ]
     }
   ]
 ]
+#>logical_select --drilldowns[item].columns[price_with_tax].flags "COLUMN_SCALAR" --drilldowns[item].columns[price_with_tax].stage "initial" --drilldowns[item].columns[price_with_tax].type "UInt32" --drilldowns[item].columns[price_with_tax].value "price * 1.08" --drilldowns[item].keys "items" --drilldowns[item].output_columns "_key,_nsubrecs,price,price_with_tax" --drilldowns[item].sort_keys "price" --drilldowns[real_price].keys "price_with_tax" --drilldowns[real_price].table "item" --limit "0" --logical_table "Logs" --output_columns "_id" --shard_key "timestamp"
+#:000000000000000 select(2)[Logs_20170315]
+#:000000000000000 select(2)[Logs_20170316]
+#:000000000000000 select(2)[Logs_20170317]
+#:000000000000000 drilldowns[item](6)
+#:000000000000000 drilldowns[item].columns[price_with_tax](6)
+#:000000000000000 drilldowns[real_price](3)
+#:000000000000000 output(0)
+#:000000000000000 drilldowns[item].sort(6): price
+#:000000000000000 output.drilldowns[item](6)
+#:000000000000000 output.drilldowns[real_price](3)
+#<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldowns/columns/stage/initial/drilldown.test (+2 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/columns/stage/initial/drilldown.test    2019-05-13 15:48:37 +0900 (2b74329e9)
+++ test/command/suite/sharding/logical_select/drilldowns/columns/stage/initial/drilldown.test    2019-05-13 17:54:59 +0900 (70387e8d0)
@@ -45,6 +45,7 @@ load --table Logs_20170317
 {"timestamp": "2017/03/17 20:00:00", "items": ["Drink", "Note"]}
 ]
 
+#@collect-query-log true
 logical_select Logs \
   --shard_key timestamp \
   --output_columns _id \
@@ -58,3 +59,4 @@ logical_select Logs \
   --drilldowns[item].columns[price_with_tax].value 'price * 1.08' \
   --drilldowns[real_price].table item \
   --drilldowns[real_price].keys price_with_tax
+#@collect-query-log false

  Modified: test/command/suite/sharding/logical_select/drilldowns/columns/window_function/window_sum/ascending.expected (+10 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/columns/window_function/window_sum/ascending.expected    2019-05-13 15:48:37 +0900 (5199ccc92)
+++ test/command/suite/sharding/logical_select/drilldowns/columns/window_function/window_sum/ascending.expected    2019-05-13 17:54:59 +0900 (b3e8bb8f2)
@@ -122,3 +122,13 @@ logical_select Logs   --shard_key timestamp   --output_columns _id   --limit 0
     }
   ]
 ]
+#>logical_select --drilldowns[item].columns[sun].flags "COLUMN_SCALAR" --drilldowns[item].columns[sun].stage "initial" --drilldowns[item].columns[sun].type "UInt32" --drilldowns[item].columns[sun].value "window_sum(price)" --drilldowns[item].columns[sun].window.sort_keys "price" --drilldowns[item].keys "item" --drilldowns[item].output_columns "sun, _key, price" --drilldowns[item].sort_keys "sun" --limit "0" --logical_table "Logs" --output_columns "_id" --shard_key "timestamp"
+#:000000000000000 select(2)[Logs_20170315]
+#:000000000000000 select(2)[Logs_20170316]
+#:000000000000000 select(2)[Logs_20170317]
+#:000000000000000 drilldowns[item](6)
+#:000000000000000 drilldowns[item].columns[sun](6)
+#:000000000000000 output(0)
+#:000000000000000 drilldowns[item].sort(6): sun
+#:000000000000000 output.drilldowns[item](6)
+#<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldowns/columns/window_function/window_sum/ascending.test (+2 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/columns/window_function/window_sum/ascending.test    2019-05-13 15:48:37 +0900 (908323a88)
+++ test/command/suite/sharding/logical_select/drilldowns/columns/window_function/window_sum/ascending.test    2019-05-13 17:54:59 +0900 (c2a50f390)
@@ -45,6 +45,7 @@ load --table Logs_20170317
 {"timestamp": "2017/03/17 20:00:00", "item": "item6"}
 ]
 
+#@collect-query-log true
 logical_select Logs \
   --shard_key timestamp \
   --output_columns _id \
@@ -57,3 +58,4 @@ logical_select Logs \
   --drilldowns[item].columns[sun].window.sort_keys price \
   --drilldowns[item].sort_keys 'sun' \
   --drilldowns[item].output_columns 'sun, _key, price'
+#@collect-query-log false

  Modified: test/command/suite/sharding/logical_select/drilldowns/filter/key.expected (+10 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/filter/key.expected    2019-05-13 15:48:37 +0900 (e6d955514)
+++ test/command/suite/sharding/logical_select/drilldowns/filter/key.expected    2019-05-13 17:54:59 +0900 (53d3ef127)
@@ -135,3 +135,13 @@ logical_select Logs timestamp   --limit 0   --drilldowns[action].keys action   -
     }
   ]
 ]
+#>logical_select --drilldowns[action].filter "_key == \"Restart\"" --drilldowns[action].keys "action" --limit "0" --logical_table "Logs" --shard_key "timestamp"
+#:000000000000000 select(2)[Logs_20150203]
+#:000000000000000 select(3)[Logs_20150204]
+#:000000000000000 select(4)[Logs_20150205]
+#:000000000000000 drilldowns[action](3)
+#:000000000000000 filter(1): #<accessor _key(anonymous)> equal "Restart"
+#:000000000000000 drilldowns[action].filter(1)
+#:000000000000000 output(0)
+#:000000000000000 output.drilldowns[action](1)
+#<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldowns/filter/key.test (+2 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/filter/key.test    2019-05-13 15:48:37 +0900 (856741f09)
+++ test/command/suite/sharding/logical_select/drilldowns/filter/key.test    2019-05-13 17:54:59 +0900 (990469cb6)
@@ -74,7 +74,9 @@ load --table Logs_20150205
 }
 ]
 
+#@collect-query-log true
 logical_select Logs timestamp \
   --limit 0 \
   --drilldowns[action].keys action \
   --drilldowns[action].filter '_key == "Restart"'
+#@collect-query-log false

  Modified: test/command/suite/sharding/logical_select/drilldowns/limit/negative.expected (+2 -1)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/limit/negative.expected    2019-05-13 15:48:37 +0900 (c98a5fe65)
+++ test/command/suite/sharding/logical_select/drilldowns/limit/negative.expected    2019-05-13 17:54:59 +0900 (e2b4a6a13)
@@ -178,6 +178,7 @@ logical_select Logs timestamp   --limit 0   --drilldowns[action_date].keys actio
 #:000000000000000 select(2)[Logs_20150203]
 #:000000000000000 select(3)[Logs_20150204]
 #:000000000000000 select(4)[Logs_20150205]
+#:000000000000000 drilldowns[action_date](5)
 #:000000000000000 output(0)
-#:000000000000000 output.drilldowns(4)
+#:000000000000000 output.drilldowns[action_date](4)
 #<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldowns/limit/positive.expected (+2 -1)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/limit/positive.expected    2019-05-13 15:48:37 +0900 (beebb9235)
+++ test/command/suite/sharding/logical_select/drilldowns/limit/positive.expected    2019-05-13 17:54:59 +0900 (9c8ac6087)
@@ -163,6 +163,7 @@ logical_select Logs timestamp   --limit 0   --drilldowns[action_date].keys actio
 #:000000000000000 select(2)[Logs_20150203]
 #:000000000000000 select(3)[Logs_20150204]
 #:000000000000000 select(4)[Logs_20150205]
+#:000000000000000 drilldowns[action_date](5)
 #:000000000000000 output(0)
-#:000000000000000 output.drilldowns(1)
+#:000000000000000 output.drilldowns[action_date](1)
 #<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldowns/offset/negative.expected (+2 -1)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/offset/negative.expected    2019-05-13 15:48:37 +0900 (c6177cd9b)
+++ test/command/suite/sharding/logical_select/drilldowns/offset/negative.expected    2019-05-13 17:54:59 +0900 (fa125e008)
@@ -163,6 +163,7 @@ logical_select Logs timestamp   --limit 0   --drilldowns[action_date].keys actio
 #:000000000000000 select(2)[Logs_20150203]
 #:000000000000000 select(3)[Logs_20150204]
 #:000000000000000 select(4)[Logs_20150205]
+#:000000000000000 drilldowns[action_date](5)
 #:000000000000000 output(0)
-#:000000000000000 output.drilldowns(1)
+#:000000000000000 output.drilldowns[action_date](1)
 #<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldowns/offset/positive.expected (+2 -1)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/offset/positive.expected    2019-05-13 15:48:37 +0900 (33e24a326)
+++ test/command/suite/sharding/logical_select/drilldowns/offset/positive.expected    2019-05-13 17:54:59 +0900 (dcc83fc28)
@@ -178,6 +178,7 @@ logical_select Logs timestamp   --limit 0   --drilldowns[action_date].keys actio
 #:000000000000000 select(2)[Logs_20150203]
 #:000000000000000 select(3)[Logs_20150204]
 #:000000000000000 select(4)[Logs_20150205]
+#:000000000000000 drilldowns[action_date](5)
 #:000000000000000 output(0)
-#:000000000000000 output.drilldowns(4)
+#:000000000000000 output.drilldowns[action_date](4)
 #<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldowns/sort_keys/multiple/one_shard.expected (+7 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/sort_keys/multiple/one_shard.expected    2019-05-13 15:48:37 +0900 (dd7c899e2)
+++ test/command/suite/sharding/logical_select/drilldowns/sort_keys/multiple/one_shard.expected    2019-05-13 17:54:59 +0900 (7a36872e5)
@@ -175,3 +175,10 @@ logical_select Logs timestamp   --min "2015-02-05 00:00:00"   --min_border "incl
     }
   ]
 ]
+#>logical_select --drilldowns[action_date].keys "action,date" --drilldowns[action_date].output_columns "_value.action,_value.date,_nsubrecs" --drilldowns[action_date].sort_keys "-_nsubrecs,_value.date,_value.action" --limit "0" --logical_table "Logs" --max "2015-02-06 00:00:00" --max_border "exclude" --min "2015-02-05 00:00:00" --min_border "include" --shard_key "timestamp"
+#:000000000000000 select(5)[Logs_20150205]
+#:000000000000000 drilldowns[action_date](3)
+#:000000000000000 output(0)
+#:000000000000000 drilldowns[action_date].sort(3): -_nsubrecs,_value.date,_value.action
+#:000000000000000 output.drilldowns[action_date](3)
+#<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/drilldowns/sort_keys/multiple/one_shard.test (+2 -0)
===================================================================
--- test/command/suite/sharding/logical_select/drilldowns/sort_keys/multiple/one_shard.test    2019-05-13 15:48:37 +0900 (ae8f3bb97)
+++ test/command/suite/sharding/logical_select/drilldowns/sort_keys/multiple/one_shard.test    2019-05-13 17:54:59 +0900 (4df654501)
@@ -92,6 +92,7 @@ load --table Logs_20150205
 }
 ]
 
+#@collect-query-log true
 logical_select Logs timestamp \
   --min "2015-02-05 00:00:00" \
   --min_border "include" \
@@ -101,3 +102,4 @@ logical_select Logs timestamp \
   --drilldowns[action_date].keys action,date \
   --drilldowns[action_date].output_columns _value.action,_value.date,_nsubrecs \
   --drilldowns[action_date].sort_keys -_nsubrecs,_value.date,_value.action
+#@collect-query-log false

  Modified: test/command/suite/sharding/logical_select/sort_keys/shard_key/ascending.expected (+9 -0)
===================================================================
--- test/command/suite/sharding/logical_select/sort_keys/shard_key/ascending.expected    2019-05-13 15:48:37 +0900 (8d229a12b)
+++ test/command/suite/sharding/logical_select/sort_keys/shard_key/ascending.expected    2019-05-13 17:54:59 +0900 (7826f1b59)
@@ -140,3 +140,12 @@ logical_select Logs timestamp   --sort_keys timestamp
     ]
   ]
 ]
+#>logical_select --logical_table "Logs" --shard_key "timestamp" --sort_keys "timestamp"
+#:000000000000000 select(2)[Logs_20150203]
+#:000000000000000 select(3)[Logs_20150204]
+#:000000000000000 select(4)[Logs_20150205]
+#:000000000000000 sort(2): timestamp
+#:000000000000000 sort(3): timestamp
+#:000000000000000 sort(4): timestamp
+#:000000000000000 output(9)
+#<000000000000000 rc=0

  Modified: test/command/suite/sharding/logical_select/sort_keys/shard_key/ascending.test (+2 -0)
===================================================================
--- test/command/suite/sharding/logical_select/sort_keys/shard_key/ascending.test    2019-05-13 15:48:37 +0900 (084832bc3)
+++ test/command/suite/sharding/logical_select/sort_keys/shard_key/ascending.test    2019-05-13 17:54:59 +0900 (6d8fb8197)
@@ -62,5 +62,7 @@ load --table Logs_20150205
 }
 ]
 
+#@collect-query-log true
 logical_select Logs timestamp \
   --sort_keys timestamp
+#@collect-query-log false
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.osdn.me/mailman/archives/groonga-commit/attachments/20190513/691a3369/attachment-0001.html>


More information about the Groonga-commit mailing list
Back to archive index