From 735b97fe3379897c037392098107551c4661dfcb Mon Sep 17 00:00:00 2001 From: Vitaliy Filippov Date: Wed, 27 May 2020 19:24:50 +0300 Subject: [PATCH] Trace I/O operations (SQEs, recvmsg/sendmsg, uring_submit) --- blockstore_flush.cpp | 17 +++++++++++++++++ blockstore_impl.h | 10 ++++++++++ blockstore_stable.cpp | 10 ++++++++++ blockstore_write.cpp | 10 ++++++++++ epoll_manager.cpp | 5 +++++ msgr_receive.cpp | 5 +++++ msgr_send.cpp | 5 +++++ osd.cpp | 5 +++++ osd_primary.cpp | 2 ++ ringloop.h | 10 +++++++++- 10 files changed, 78 insertions(+), 1 deletion(-) diff --git a/blockstore_flush.cpp b/blockstore_flush.cpp index e2fa936b..678f8faa 100644 --- a/blockstore_flush.cpp +++ b/blockstore_flush.cpp @@ -33,6 +33,12 @@ journal_flusher_co::journal_flusher_co() ); } wait_count--; + if (!wait_count) + { + timespec now; + clock_gettime(CLOCK_REALTIME, &now); + printf("finished %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000); + } }; simple_callback_w = [this](ring_data_t* data) { @@ -45,6 +51,12 @@ journal_flusher_co::journal_flusher_co() ); } wait_count--; + if (!wait_count) + { + timespec now; + clock_gettime(CLOCK_REALTIME, &now); + printf("finished %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000); + } }; } @@ -122,6 +134,11 @@ void journal_flusher_t::release_trim() #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)\ {\ diff --git a/blockstore_impl.h b/blockstore_impl.h index 7a0528f1..f1091add 100644 --- a/blockstore_impl.h +++ b/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)\ {\ diff --git a/blockstore_stable.cpp b/blockstore_stable.cpp index a8dda0e9..22e328fe 100644 --- a/blockstore_stable.cpp +++ b/blockstore_stable.cpp @@ -147,6 +147,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) { @@ -237,6 +242,11 @@ void blockstore_impl_t::handle_stable_event(ring_data_t *data, blockstore_op_t * PRIV(op)->pending_ops--; if (PRIV(op)->pending_ops == 0) { + { + timespec now; + clock_gettime(CLOCK_REALTIME, &now); + printf("finished %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000); + } PRIV(op)->op_state++; if (!continue_stable(op)) { diff --git a/blockstore_write.cpp b/blockstore_write.cpp index b4f674cd..6cbebab9 100644 --- a/blockstore_write.cpp +++ b/blockstore_write.cpp @@ -302,6 +302,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) { @@ -333,6 +338,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 diff --git a/epoll_manager.cpp b/epoll_manager.cpp index e8f0edad..e94a75fa 100644 --- a/epoll_manager.cpp +++ b/epoll_manager.cpp @@ -57,6 +57,11 @@ void epoll_manager_t::set_fd_handler(int fd, std::function handl void epoll_manager_t::handle_epoll_events() { + { + timespec now; + clock_gettime(CLOCK_REALTIME, &now); + printf("epoll %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000); + } io_uring_sqe *sqe = ringloop->get_sqe(); if (!sqe) { diff --git a/msgr_receive.cpp b/msgr_receive.cpp index 08faedc3..517716b7 100644 --- a/msgr_receive.cpp +++ b/msgr_receive.cpp @@ -24,6 +24,11 @@ void osd_messenger_t::read_requests() { result = -errno; } + { + timespec now; + clock_gettime(CLOCK_REALTIME, &now); + printf("recvmsg done %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000); + } handle_read(result, peer_fd); } } diff --git a/msgr_send.cpp b/msgr_send.cpp index b04f8b61..1984c130 100644 --- a/msgr_send.cpp +++ b/msgr_send.cpp @@ -81,6 +81,11 @@ bool osd_messenger_t::try_send(osd_client_t & cl) int result = sendmsg(peer_fd, &cl.write_msg, MSG_NOSIGNAL); if (result < 0) result = -errno; + { + timespec now; + clock_gettime(CLOCK_REALTIME, &now); + printf("sendmsg done %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000); + } handle_send(result, peer_fd); return true; } diff --git a/osd.cpp b/osd.cpp index f73dec79..2a7325b3 100644 --- a/osd.cpp +++ b/osd.cpp @@ -241,6 +241,11 @@ void osd_t::set_fd_handler(int fd, std::function handler) void osd_t::handle_epoll_events() { + { + timespec now; + clock_gettime(CLOCK_REALTIME, &now); + printf("epoll %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000); + } io_uring_sqe *sqe = ringloop->get_sqe(); if (!sqe) { diff --git a/osd_primary.cpp b/osd_primary.cpp index dc8c4021..b07833da 100644 --- a/osd_primary.cpp +++ b/osd_primary.cpp @@ -198,6 +198,7 @@ void osd_t::continue_primary_write(osd_op_t *cur_op) else if (op_data->st == 8) goto resume_8; else if (op_data->st == 9) goto resume_9; assert(op_data->st == 0); + printf("primary_write\n"); if (!check_write_queue(cur_op, pg)) { return; @@ -389,6 +390,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 diff --git a/ringloop.h b/ringloop.h index ed1b915b..d879cb03 100644 --- a/ringloop.h +++ b/ringloop.h @@ -4,6 +4,8 @@ #define _LARGEFILE64_SOURCE #endif +#include +#include #include #include #include @@ -158,7 +160,13 @@ public: } inline int submit() { - return io_uring_submit(&ring); + int r = io_uring_submit(&ring); + { + timespec now; + clock_gettime(CLOCK_REALTIME, &now); + printf("submit %s %d %ld.%06ld\n", __FILE__, __LINE__, now.tv_sec, now.tv_nsec/1000); + } + return r; } inline int wait() {