opt trans debug log

Author: mag1c-h

ucm/store/cache/cc/dump_queue.cc

@@ -82,6 +82,8 @@ void DumpQueue::DispatchOneTask(Trans::Stream* stream, size_t tensorSize, TaskPa
 {
     auto& task = pair.first;
     auto& waiter = pair.second;
+    auto wait = NowTime::Now() - waiter->startTp;
+    UC_DEBUG("Cache task({}) start running, wait {:06f}s.", task->id, wait);
     if (!failureSet_->Contains(task->id)) {
         auto s = DumpOneTask(stream, tensorSize, task);
         if (s.Failure()) [[unlikely]] { failureSet_->Insert(task->id); }

ucm/store/cache/cc/load_queue.cc

@@ -65,6 +65,8 @@ void LoadQueue::DispatchOneTask(TaskPair&& pair)
 {
     auto& task = pair.first;
     auto& waiter = pair.second;
+    auto wait = NowTime::Now() - waiter->startTp;
+    UC_DEBUG("Cache task({}) start running, wait {:06f}s.", task->id, wait);
     if (failureSet_->Contains(task->id)) {
         waiter->Done();
         return;

ucm/store/cache/cc/trans_manager.h

@@ -58,11 +58,10 @@ class TransManager : public Detail::TaskWrapper<TransTask, Detail::TaskHandle> {
         const auto num = t->desc.size();
         const auto size = shardSize_ * num;
         const auto tp = w->startTp;
-        UC_DEBUG("Dispatch one cache task({},{},{},{}).", id, brief, num, size);
+        UC_DEBUG("Cache task({},{},{},{}) dispatching.", id, brief, num, size);
         w->SetEpilog([id, brief = std::move(brief), num, size, tp] {
             auto cost = NowTime::Now() - tp;
-            UC_DEBUG("Cache task({},{},{},{}) finished, cost {:06f}s, bw={:06f}GB/s.", id, brief,
-                     num, size, cost, size / cost / 1e9);
+            UC_DEBUG("Cache task({},{},{},{}) finished, cost {:06f}s.", id, brief, num, size, cost);
         });
         if (t->type == TransTask::Type::LOAD) {
             loadQ_.Submit(t, w);

ucm/store/posix/cc/trans_manager.h

@@ -50,11 +50,10 @@ class TransManager : public Detail::TaskWrapper<TransTask, Detail::TaskHandle> {
         const auto num = t->desc.size();
         const auto size = shardSize_ * num;
         const auto tp = w->startTp;
-        UC_DEBUG("Dispatch one posix task({},{},{},{}).", id, brief, num, size);
+        UC_DEBUG("Posix task({},{},{},{}) dispatching.", id, brief, num, size);
         w->SetEpilog([id, brief = std::move(brief), num, size, tp] {
             auto cost = NowTime::Now() - tp;
-            UC_DEBUG("Posix task({},{},{},{}) finished, cost {:06f}s, bw={:06f}GB/s.", id, brief,
-                     num, size, cost, size / cost / 1e9);
+            UC_DEBUG("Posix task({},{},{},{}) finished, cost {:06f}s.", id, brief, num, size, cost);
         });
         queue_.Push(t, w);
     }

ucm/store/posix/cc/trans_queue.cc

@@ -51,11 +51,16 @@ void TransQueue::Push(TaskPtr task, WaiterPtr waiter)
     for (auto&& shard : task->desc) {
         ios.emplace_back<IoUnit>({task->id, task->type, std::move(shard), waiter});
     }
+    ios.front().firstIo = true;
     pool_.Push(ios);
 }
 
 void TransQueue::Worker(IoUnit& ios)
 {
+    if (ios.firstIo) {
+        auto wait = NowTime::Now() - ios.waiter->startTp;
+        UC_DEBUG("Posix task({}) start running, wait {:06f}s.", ios.owner, wait);
+    }
     if (failureSet_->Contains(ios.owner)) {
         ios.waiter->Done();
         return;

ucm/store/posix/cc/trans_queue.h

@@ -44,6 +44,7 @@ class TransQueue {
         TransTask::Type type;
         Detail::Shard shard;
         std::shared_ptr<Latch> waiter;
+        bool firstIo{false};
     };
     TaskIdSet* failureSet_;
     const SpaceLayout* layout_;