TRACE

blockstore_flush.cpp

@@ -116,6 +116,11 @@ void journal_flusher_t::force_start()
 
 #define await_sqe(label) \
     resume_##label:\
+        {\
+            timespec now;\
+            clock_gettime(CLOCK_REALTIME, &now);\
+            printf("get_sqe %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000);\
+        }\
         sqe = bs->get_sqe();\
         if (!sqe)\
         {\

blockstore_impl.h

@@ -62,6 +62,11 @@
     struct ring_data_t *data = ((ring_data_t*)sqe->user_data)
 
 #define BS_SUBMIT_GET_ONLY_SQE(sqe) \
+        {\
+            timespec now;\
+            clock_gettime(CLOCK_REALTIME, &now);\
+            printf("get_sqe %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000);\
+        }\
     struct io_uring_sqe *sqe = get_sqe();\
     if (!sqe)\
     {\
@@ -71,6 +76,11 @@
     }
 
 #define BS_SUBMIT_GET_SQE_DECL(sqe) \
+        {\
+            timespec now;\
+            clock_gettime(CLOCK_REALTIME, &now);\
+            printf("get_sqe %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000);\
+        }\
     sqe = get_sqe();\
     if (!sqe)\
     {\

blockstore_stable.cpp

@@ -153,6 +153,11 @@ resume_2:
 resume_3:
     if (!disable_journal_fsync)
     {
+        {
+            timespec now;
+            clock_gettime(CLOCK_REALTIME, &now);
+            printf("get_sqe %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000);
+        }
         io_uring_sqe *sqe = get_sqe();
         if (!sqe)
         {

blockstore_write.cpp

@@ -296,6 +296,11 @@ int blockstore_impl_t::continue_write(blockstore_op_t *op)
         return 1;
 resume_2:
     // Only for the immediate_commit mode: prepare and submit big_write journal entry
+        {
+            timespec now;
+            clock_gettime(CLOCK_REALTIME, &now);
+            printf("get_sqe %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000);
+        }
     sqe = get_sqe();
     if (!sqe)
     {
@@ -323,6 +328,11 @@ resume_2:
     return 1;
 resume_4:
     // Switch object state
+        {
+            timespec now;
+            clock_gettime(CLOCK_REALTIME, &now);
+            printf("write_done %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000);
+        }
 #ifdef BLOCKSTORE_DEBUG
     printf("Ack write %lu:%lu v%lu = %d\n", op->oid.inode, op->oid.stripe, op->version, dirty_it->second.state);
 #endif

osd.cpp

@@ -261,6 +261,11 @@ void osd_t::set_fd_handler(int fd, bool out, std::function<void(int, int)> handl
 void osd_t::handle_epoll_events()
 {
     wait_state = 0;
+        {
+            timespec now;
+            clock_gettime(CLOCK_REALTIME, &now);
+            printf("get_sqe %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000);
+        }
     io_uring_sqe *sqe = ringloop->get_sqe();
     if (!sqe)
     {
@@ -324,6 +329,7 @@ restart:
             cb(events[i].data.fd, events[i].events);
         }
     }
+    printf("%d events\n", nfds);
     if (nfds == MAX_EPOLL_EVENTS)
     {
         goto restart;

osd_primary.cpp

@@ -199,6 +199,7 @@ void osd_t::continue_primary_write(osd_op_t *cur_op)
     else if (op_data->st == 7) goto resume_7;
     else if (op_data->st == 8) goto resume_8;
     assert(op_data->st == 0);
+    printf("primary_write\n");
     if (!check_write_queue(cur_op, pg))
     {
         return;
@@ -387,6 +388,7 @@ void osd_t::continue_primary_sync(osd_op_t *cur_op)
     else if (op_data->st == 5) goto resume_5;
     else if (op_data->st == 6) goto resume_6;
     assert(op_data->st == 0);
+    printf("primary_sync\n");
     if (syncs_in_progress.size() > 0)
     {
         // Wait for previous syncs, if any

osd_receive.cpp

@@ -6,6 +6,11 @@ void cluster_client_t::read_requests()
     {
         int peer_fd = read_ready_clients[i];
         auto & cl = clients[peer_fd];
+        {
+            timespec now;
+            clock_gettime(CLOCK_REALTIME, &now);
+            printf("get_sqe %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000);
+        }
         io_uring_sqe* sqe = ringloop->get_sqe();
         if (!sqe)
         {

osd_send.cpp

@@ -25,6 +25,11 @@ void cluster_client_t::outbox_push(osd_op_t *cur_op)
 bool cluster_client_t::try_send(osd_client_t & cl)
 {
     int peer_fd = cl.peer_fd;
+        {
+            timespec now;
+            clock_gettime(CLOCK_REALTIME, &now);
+            printf("get_sqe %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000);
+        }
     io_uring_sqe* sqe = ringloop->get_sqe();
     if (!sqe)
     {