query_log/bug: scan_byte_cost_ms is 0

[BohuTANG]

Summary

Ontime dataset, query is:
SELECT DayOfWeek, count(*) AS c FROM ontime WHERE Year >= 2000 AND Year <= 2008 GROUP BY DayOfWeek ORDER BY c DESC

query_log:

           log_type: 2
       handler_type: MySQL
          tenant_id: test_tenant
         cluster_id: test_cluster
           sql_user: root
     sql_user_quota: UserQuota { max_cpu: 0, max_memory_in_bytes: 0, max_storage_in_bytes: 0 }
sql_user_privileges: UserGrantSet { entries: [GrantEntry { user: "root", host_pattern: "127.0.0.1", object: Global, privileges: BitFlags<UserPrivilegeType>(0b1111111101111, Usage | Select | Insert | Update | Delete | Create | Drop | Alter | S
uper | CreateUser | CreateRole | Grant) }], roles: {} }
           query_id: 14fb2884-230a-4608-855b-0e4b2bbf19d7
         query_kind: SelectPlan
         query_text: SELECT DayOfWeek, count(*) AS c FROM ontime WHERE Year >= 2000 AND Year <= 2008 GROUP BY DayOfWeek ORDER BY c DESC
         event_date: 2022-02-26
         event_time: 1645872355531
   current_database: default
          databases: 
             tables: 
            columns: 
        projections: 
       written_rows: 0
      written_bytes: 0
          scan_rows: 195662213
         scan_bytes: 586986639
  scan_byte_cost_ms: 0
         scan_seeks: 0
  scan_seek_cost_ms: 0
    scan_partitions: 196
   total_partitions: 196
        result_rows: 7
       result_bytes: 63
          cpu_usage: 8
       memory_usage: 2672
        client_info: 
     client_address: Some(127.0.0.1:39130)
     exception_code: 0
     exception_text: 
        stack_trace: 
     server_version: 
              extra: 

[BohuTANG]

Just found that the scan_byte_cost_ms metric we do not count it, where the place to add?

#[async_trait]
impl Accessor for DalContext {
    async fn read(&self, args: &OpRead) -> DalResult<BoxedAsyncReader> {
        let metrics = self.metrics.clone();

        // TODO(xuanwo): Maybe it's better to move into metrics.
        self.inner.as_ref().unwrap().read(args).await.map(|reader| {
            let r = CallbackReader::new(reader, move |n| {
                let mut metrics = metrics.write();
                metrics.read_bytes += n;
            });

            Box::new(r) as BoxedAsyncReader
        })
    }

Need your help @Xuanwo

[Xuanwo]

Seems fixed by #4262?

[BohuTANG]

Seems fixed by #4262?

Not yet.
Still not sure where to count scan_byte_cost_ms in the async fn read.

#[async_trait]
impl Accessor for DalContext {
    async fn read(&self, args: &OpRead) -> DalResult<BoxedAsyncReader> {
        let metrics = self.metrics.clone();
         let start = now();
        // TODO(xuanwo): Maybe it's better to move into metrics.
        self.inner.as_ref().unwrap().read(args).await.map(|reader| {
            let r = CallbackReader::new(reader, move |n| {
                let mut metrics = metrics.write();
                metrics.read_bytes += n;
                let end = now();
                merics.inc_scan_byte_cost(end-start); -- here is right?
            });

            Box::new(r) as BoxedAsyncReader
        })
    }

[Xuanwo]

Ok, I got the problem. The callback was triggered at the end of this read, so we cannot calculate the cost of every read operation. Let me find a solution for it.

[Xuanwo]

Should be addressed by #4298

[BohuTANG]

#4298 (comment)