Added trace log where epoll_wait returns and to where read fomr/write to socket decicion is made.

This commit is contained in:
vraatikka
2013-08-15 20:16:23 +03:00
parent 90e6e11923
commit a1b05359ac
2 changed files with 62 additions and 17 deletions

View File

@ -330,6 +330,7 @@ dcb_read(DCB *dcb, GWBUF **head)
{ {
GWBUF *buffer = NULL; GWBUF *buffer = NULL;
int b, n = 0; int b, n = 0;
pthread_t tid = pthread_self();
ioctl(dcb->fd, FIONREAD, &b); ioctl(dcb->fd, FIONREAD, &b);
while (b > 0) while (b > 0)
@ -358,6 +359,12 @@ int b, n = 0;
return n; 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 // append read data to the gwbuf
*head = gwbuf_append(*head, buffer); *head = gwbuf_append(*head, buffer);
@ -378,6 +385,7 @@ int
dcb_write(DCB *dcb, GWBUF *queue) dcb_write(DCB *dcb, GWBUF *queue)
{ {
int w, saved_errno = 0; int w, saved_errno = 0;
pthread_t tid = pthread_self();
spinlock_acquire(&dcb->writeqlock); spinlock_acquire(&dcb->writeqlock);
if (dcb->writeq) if (dcb->writeq)
@ -393,6 +401,12 @@ int w, saved_errno = 0;
*/ */
dcb->writeq = gwbuf_append(dcb->writeq, queue); dcb->writeq = gwbuf_append(dcb->writeq, queue);
dcb->stats.n_buffered++; 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 else
{ {
@ -423,6 +437,12 @@ int w, saved_errno = 0;
{ {
/* We didn't write all the data */ /* 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 */ /* Buffer the balance of any data */
dcb->writeq = queue; dcb->writeq = queue;

View File

@ -143,6 +143,8 @@ poll_waitevents(void *arg)
struct epoll_event events[MAX_EVENTS]; struct epoll_event events[MAX_EVENTS];
int i, nfds; int i, nfds;
int thread_id = (int)arg; int thread_id = (int)arg;
pthread_t tid = pthread_self();
bool no_op = FALSE;
/* Add this thread to the bitmask of running polling threads */ /* Add this thread to the bitmask of running polling threads */
bitmask_set(&poll_mask, thread_id); bitmask_set(&poll_mask, thread_id);
@ -153,31 +155,39 @@ int thread_id = (int)arg;
{ {
} }
#else #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) if ((nfds = epoll_wait(epoll_fd, events, MAX_EVENTS, 0)) == -1)
{ {
int eno = errno; int eno = errno;
errno = 0; errno = 0;
skygw_log_write(LOGFILE_TRACE, skygw_log_write(LOGFILE_TRACE,
"epoll_wait returned %d, errno %d", "%lu [poll_waitevents] epoll_wait returned %d, errno %d",
tid,
nfds, nfds,
eno); eno);
no_op = FALSE;
} }
else if (nfds == 0) else if (nfds == 0)
{ {
int eno = 0;
if ((nfds = epoll_wait(epoll_fd, events, MAX_EVENTS, EPOLL_TIMEOUT)) == -1) 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);
} }
#endif #endif
if (nfds > 0) if (nfds > 0)
{ {
skygw_log_write(
LOGFILE_TRACE,
"%lu [poll_waitevents] epoll_wait found %d fds",
tid,
nfds);
atomic_add(&pollStats.n_polls, 1); atomic_add(&pollStats.n_polls, 1);
for (i = 0; i < nfds; i++) for (i = 0; i < nfds; i++)
{ {
@ -203,6 +213,10 @@ int thread_id = (int)arg;
} }
if (ev & EPOLLOUT) if (ev & EPOLLOUT)
{ {
skygw_log_write(LOGFILE_TRACE,
"%lu [poll_waitevents] Write in %d",
tid,
dcb->fd);
atomic_add(&pollStats.n_write, 1); atomic_add(&pollStats.n_write, 1);
dcb->func.write_ready(dcb); dcb->func.write_ready(dcb);
} }
@ -210,16 +224,27 @@ int thread_id = (int)arg;
{ {
if (dcb->state == DCB_STATE_LISTENING) if (dcb->state == DCB_STATE_LISTENING)
{ {
skygw_log_write(
LOGFILE_TRACE,
"%lu [poll_waitevents] Accept in %d",
tid,
dcb->fd);
atomic_add(&pollStats.n_accept, 1); atomic_add(&pollStats.n_accept, 1);
dcb->func.accept(dcb); dcb->func.accept(dcb);
} }
else else
{ {
skygw_log_write(
LOGFILE_TRACE,
"%lu [poll_waitevents] Read in %d",
tid,
dcb->fd);
atomic_add(&pollStats.n_read, 1); atomic_add(&pollStats.n_read, 1);
dcb->func.read(dcb); dcb->func.read(dcb);
} }
} }
} } /**< for */
no_op = FALSE;
} }
dcb_process_zombies(thread_id); dcb_process_zombies(thread_id);
if (shutdown) if (shutdown)
@ -228,7 +253,7 @@ int thread_id = (int)arg;
bitmask_clear(&poll_mask, thread_id); bitmask_clear(&poll_mask, thread_id);
return; return;
} }
} } /**< while(1) */
} }
/** /**