feature: stats do command duration in slow log (#990)

delete debug log in pika_command.cc

include/pika_client_conn.h

@@ -78,7 +78,7 @@ class PikaClientConn: public pink::RedisConn {
   std::shared_ptr<Cmd> DoCmd(const PikaCmdArgsType& argv, const std::string& opt,
       std::shared_ptr<std::string> resp_ptr);
 
-  void ProcessSlowlog(const PikaCmdArgsType& argv, uint64_t start_us);
+  void ProcessSlowlog(const PikaCmdArgsType& argv, uint64_t start_us, uint64_t do_duration);
   void ProcessMonitor(const PikaCmdArgsType& argv);
 
   void ExecRedisCmd(const PikaCmdArgsType& argv, std::shared_ptr<std::string> resp_ptr);

include/pika_command.h

@@ -436,7 +436,7 @@ class Cmd: public std::enable_shared_from_this<Cmd> {
     HintKeys hint_keys;
   };
   Cmd(const std::string& name, int arity, uint16_t flag)
-    : name_(name), arity_(arity), flag_(flag), stage_(kNone) {}
+    : name_(name), arity_(arity), flag_(flag), stage_(kNone), do_duration_(0) {}
   virtual ~Cmd() {}
 
   virtual std::vector<std::string> current_key() const;
@@ -463,6 +463,7 @@ class Cmd: public std::enable_shared_from_this<Cmd> {
   bool is_multi_partition()  const;
   bool is_classic_mode()     const;
   bool HashtagIsConsistent(const std::string& lhs, const std::string& rhs) const;
+  uint64_t GetDoDuration() const { return do_duration_; };
 
   std::string name() const;
   CmdRes& res();
@@ -505,6 +506,7 @@ class Cmd: public std::enable_shared_from_this<Cmd> {
   std::weak_ptr<pink::PinkConn> conn_;
   std::weak_ptr<std::string> resp_;
   CmdStage stage_;
+  uint64_t do_duration_;
 
  private:
   virtual void DoInitial() = 0;

src/pika_client_conn.cc

@@ -127,7 +127,7 @@ std::shared_ptr<Cmd> PikaClientConn::DoCmd(
   c_ptr->Execute();
 
   if (g_pika_conf->slowlog_slower_than() >= 0) {
-    ProcessSlowlog(argv, start_us);
+    ProcessSlowlog(argv, start_us, c_ptr->GetDoDuration());
   }
   if (g_pika_conf->consensus_level() != 0 && c_ptr->is_write()) {
     c_ptr->SetStage(Cmd::kExecuteStage);
@@ -136,7 +136,7 @@ std::shared_ptr<Cmd> PikaClientConn::DoCmd(
   return c_ptr;
 }
 
-void PikaClientConn::ProcessSlowlog(const PikaCmdArgsType& argv, uint64_t start_us) {
+void PikaClientConn::ProcessSlowlog(const PikaCmdArgsType& argv, uint64_t start_us, uint64_t do_duration) {
   int32_t start_time = start_us / 1000000;
   int64_t duration = slash::NowMicros() - start_us;
   if (duration > g_pika_conf->slowlog_slower_than()) {
@@ -160,7 +160,7 @@ void PikaClientConn::ProcessSlowlog(const PikaCmdArgsType& argv, uint64_t start_
       LOG(ERROR) << "ip_port: " << ip_port() << ", table: " << current_table_
         << ", command:" << slow_log << ", command_size: " << cmd_size - 1
         << ", arguments: " << argv.size() << ", start_time(s): " << start_time
-        << ", duration(us): " << duration;
+        << ", duration(us): " << duration << ", do_duration_(us): " << do_duration;
     }
   }
 }
@@ -237,7 +237,7 @@ void PikaClientConn::DoExecTask(void* arg) {
   cmd_ptr->SetStage(Cmd::kExecuteStage);
   cmd_ptr->Execute();
   if (g_pika_conf->slowlog_slower_than() >= 0) {
-    conn_ptr->ProcessSlowlog(cmd_ptr->argv(), start_us);
+     conn_ptr->ProcessSlowlog(cmd_ptr->argv(), start_us, cmd_ptr->GetDoDuration());
   }
 
   std::shared_ptr<SyncMasterPartition> partition =

src/pika_command.cc

@@ -657,8 +657,14 @@ void Cmd::InternalProcessCommand(std::shared_ptr<Partition> partition,
     }
   }
 
+  uint64_t start_us = 0;
+  if (g_pika_conf->slowlog_slower_than() >= 0) {
+    start_us = slash::NowMicros();
+  }
   DoCommand(partition, hint_keys);
-
+  if (g_pika_conf->slowlog_slower_than() >= 0) {
+    do_duration_  += slash::NowMicros() - start_us;
+  }
   DoBinlog(sync_partition);
 
   if (is_write()) {
@@ -733,7 +739,6 @@ void Cmd::ProcessMultiPartitionCmd() {
     res_.SetRes(CmdRes::kErrOther, "Table not found");
   }
   for (auto& key : cur_key) {
-    LOG(INFO) << "process key: "<< key;
     // in sharding mode we select partition by key
     uint32_t partition_id =  g_pika_cmd_table_manager->DistributeKey(key, table->PartitionNum());
     std::unordered_map<uint32_t, ProcessArg>::iterator iter = process_map.find(partition_id);