From a1b05359acd52dfc17f979022202f44c7ed45788 Mon Sep 17 00:00:00 2001 From: vraatikka Date: Thu, 15 Aug 2013 20:16:23 +0300 Subject: [PATCH] Added trace log where epoll_wait returns and to where read fomr/write to socket decicion is made. --- server/core/dcb.c | 24 ++++++++++++++++++-- server/core/poll.c | 55 +++++++++++++++++++++++++++++++++------------- 2 files changed, 62 insertions(+), 17 deletions(-) diff --git a/server/core/dcb.c b/server/core/dcb.c index 1cebad9de..576b287db 100644 --- a/server/core/dcb.c +++ b/server/core/dcb.c @@ -328,8 +328,9 @@ GWPROTOCOL *funcs; int dcb_read(DCB *dcb, GWBUF **head) { -GWBUF *buffer = NULL; -int b, n = 0; +GWBUF *buffer = NULL; +int b, n = 0; +pthread_t tid = pthread_self(); ioctl(dcb->fd, FIONREAD, &b); while (b > 0) @@ -358,6 +359,12 @@ int b, n = 0; return n; } + skygw_log_write( + LOGFILE_TRACE, + "%lu [dcb_read] Read %d Bytes from %d", + tid, + n, + dcb->fd); // append read data to the gwbuf *head = gwbuf_append(*head, buffer); @@ -378,6 +385,7 @@ int dcb_write(DCB *dcb, GWBUF *queue) { int w, saved_errno = 0; +pthread_t tid = pthread_self(); spinlock_acquire(&dcb->writeqlock); if (dcb->writeq) @@ -393,6 +401,12 @@ int w, saved_errno = 0; */ dcb->writeq = gwbuf_append(dcb->writeq, queue); dcb->stats.n_buffered++; + skygw_log_write( + LOGFILE_TRACE, + "%lu [dcb_write] Append to writequeue. %d writes buffered for %d", + tid, + dcb->stats.n_buffered, + dcb->fd); } else { @@ -423,6 +437,12 @@ int w, saved_errno = 0; { /* We didn't write all the data */ } + skygw_log_write( + LOGFILE_TRACE, + "%lu [dcb_write] Wrote %d Bytes to %d", + tid, + w, + dcb->fd); } /* Buffer the balance of any data */ dcb->writeq = queue; diff --git a/server/core/poll.c b/server/core/poll.c index d3e622420..5262140f0 100644 --- a/server/core/poll.c +++ b/server/core/poll.c @@ -143,6 +143,8 @@ poll_waitevents(void *arg) struct epoll_event events[MAX_EVENTS]; int i, nfds; int thread_id = (int)arg; +pthread_t tid = pthread_self(); +bool no_op = FALSE; /* Add this thread to the bitmask of running polling threads */ bitmask_set(&poll_mask, thread_id); @@ -153,31 +155,39 @@ int thread_id = (int)arg; { } #else + if (!no_op) { + skygw_log_write(LOGFILE_TRACE, + "%lu [poll_waitevents] > epoll_wait <", + tid); + no_op = TRUE; + } + if ((nfds = epoll_wait(epoll_fd, events, MAX_EVENTS, 0)) == -1) { int eno = errno; errno = 0; skygw_log_write(LOGFILE_TRACE, - "epoll_wait returned %d, errno %d", + "%lu [poll_waitevents] epoll_wait returned %d, errno %d", + tid, nfds, eno); + no_op = FALSE; } else if (nfds == 0) { - int eno = 0; - if ((nfds = epoll_wait(epoll_fd, events, MAX_EVENTS, EPOLL_TIMEOUT)) == -1) - { - } - eno = errno; - errno = 0; - skygw_log_write(LOGFILE_TRACE, - "After timeout, epoll_wait returned %d, errno %d", - nfds, - eno); + if ((nfds = epoll_wait(epoll_fd, events, MAX_EVENTS, EPOLL_TIMEOUT)) == -1) + { + } } #endif if (nfds > 0) { + skygw_log_write( + LOGFILE_TRACE, + "%lu [poll_waitevents] epoll_wait found %d fds", + tid, + nfds); + atomic_add(&pollStats.n_polls, 1); for (i = 0; i < nfds; i++) { @@ -203,6 +213,10 @@ int thread_id = (int)arg; } if (ev & EPOLLOUT) { + skygw_log_write(LOGFILE_TRACE, + "%lu [poll_waitevents] Write in %d", + tid, + dcb->fd); atomic_add(&pollStats.n_write, 1); dcb->func.write_ready(dcb); } @@ -210,16 +224,27 @@ int thread_id = (int)arg; { if (dcb->state == DCB_STATE_LISTENING) { - atomic_add(&pollStats.n_accept, 1); - dcb->func.accept(dcb); + skygw_log_write( + LOGFILE_TRACE, + "%lu [poll_waitevents] Accept in %d", + tid, + dcb->fd); + atomic_add(&pollStats.n_accept, 1); + dcb->func.accept(dcb); } else { + skygw_log_write( + LOGFILE_TRACE, + "%lu [poll_waitevents] Read in %d", + tid, + dcb->fd); atomic_add(&pollStats.n_read, 1); dcb->func.read(dcb); } } - } + } /**< for */ + no_op = FALSE; } dcb_process_zombies(thread_id); if (shutdown) @@ -228,7 +253,7 @@ int thread_id = (int)arg; bitmask_clear(&poll_mask, thread_id); return; } - } + } /**< while(1) */ } /**