From b1493ab199a2cf39b919cb8d0536263ae1d280aa Mon Sep 17 00:00:00 2001 From: Wilfried Goesgens Date: Tue, 24 Apr 2012 12:32:51 +0200 Subject: [PATCH] Logging: add timestamps for eventdriven IO - add the ev_now() timestamp to the contexts (just for measuring that precision should be ok...) - output the time the DNS requests take - output the time the whole SMTP delivery aproach took --- citadel/context.h | 1 + citadel/event_client.c | 29 +++++++++++++------ citadel/event_client.h | 4 +++ citadel/modules/c-ares-dns/serv_c-ares-dns.c | 5 ++++ .../modules/eventclient/serv_eventclient.c | 20 +++++++++++-- citadel/modules/smtp/serv_smtpeventclient.c | 10 +++++-- 6 files changed, 56 insertions(+), 13 deletions(-) diff --git a/citadel/context.h b/citadel/context.h index c25780360..08de75bb3 100644 --- a/citadel/context.h +++ b/citadel/context.h @@ -42,6 +42,7 @@ struct CitContext { int cs_pid; /* session ID */ int dont_term; /* for special activities like artv so we don't get killed */ + double created; /* time of birth */ time_t lastcmd; /* time of last command executed */ time_t lastidle; /* For computing idle time */ CCState state; /* thread state (see CON_ values below) */ diff --git a/citadel/event_client.c b/citadel/event_client.c index 2e19b17b4..d0e0fd9ae 100644 --- a/citadel/event_client.c +++ b/citadel/event_client.c @@ -72,17 +72,9 @@ #include "ctdl_module.h" static void IO_Timeout_callback(struct ev_loop *loop, ev_timer *watcher, int revents); - static void IO_abort_shutdown_callback(struct ev_loop *loop, ev_cleanup *watcher, - int revents) -{ - AsyncIO *IO = watcher->data; - EV_syslog(LOG_DEBUG, "EVENT Q: %s\n", __FUNCTION__); - - assert(IO->ShutdownAbort); - IO->ShutdownAbort(IO); -} + int revents); /*------------------------------------------------------------------------------ @@ -135,6 +127,7 @@ void DB_PerformNext(struct ev_loop *loop, ev_idle *watcher, int revents) { AsyncIO *IO = watcher->data; + IO->Now = ev_now(event_db); EV_syslog(LOG_DEBUG, "%s()", __FUNCTION__); become_session(IO->CitContext); @@ -185,6 +178,17 @@ extern struct ev_loop *event_base; extern ev_async AddJob; extern ev_async ExitEventLoop; +static void IO_abort_shutdown_callback(struct ev_loop *loop, + ev_cleanup *watcher, + int revents) +{ + AsyncIO *IO = watcher->data; + EV_syslog(LOG_DEBUG, "EVENT Q: %s\n", __FUNCTION__); + IO->Now = ev_now(event_base); + assert(IO->ShutdownAbort); + IO->ShutdownAbort(IO); +} + eNextState QueueEventContext(AsyncIO *IO, IO_CallBack CB) { @@ -388,6 +392,7 @@ IO_send_callback(struct ev_loop *loop, ev_io *watcher, int revents) AsyncIO *IO = watcher->data; const char *errmsg = NULL; + IO->Now = ev_now(event_base); become_session(IO->CitContext); #ifdef BIGBAD_IODBG { @@ -545,6 +550,7 @@ IO_Timeout_callback(struct ev_loop *loop, ev_timer *watcher, int revents) { AsyncIO *IO = watcher->data; + IO->Now = ev_now(event_base); ev_timer_stop (event_base, &IO->rw_timeout); become_session(IO->CitContext); @@ -572,6 +578,7 @@ IO_connfail_callback(struct ev_loop *loop, ev_timer *watcher, int revents) { AsyncIO *IO = watcher->data; + IO->Now = ev_now(event_base); ev_timer_stop (event_base, &IO->conn_fail); if (IO->SendBuf.fd != 0) @@ -603,6 +610,7 @@ IO_connfailimmediate_callback(struct ev_loop *loop, { AsyncIO *IO = watcher->data; + IO->Now = ev_now(event_base); ev_idle_stop (event_base, &IO->conn_fail_immediate); if (IO->SendBuf.fd != 0) @@ -628,6 +636,7 @@ IO_connestd_callback(struct ev_loop *loop, ev_io *watcher, int revents) { AsyncIO *IO = watcher->data; + IO->Now = ev_now(event_base); ev_io_stop(loop, &IO->conn_event); ev_timer_stop (event_base, &IO->conn_fail); set_start_callback(loop, IO, revents); @@ -639,6 +648,7 @@ IO_recv_callback(struct ev_loop *loop, ev_io *watcher, int revents) ssize_t nbytes; AsyncIO *IO = watcher->data; + IO->Now = ev_now(event_base); switch (IO->NextState) { case eReadFile: nbytes = FileRecvChunked(&IO->IOB, &errmsg); @@ -711,6 +721,7 @@ void IO_postdns_callback(struct ev_loop *loop, ev_idle *watcher, int revents) { AsyncIO *IO = watcher->data; + IO->Now = ev_now(event_base); EV_syslog(LOG_DEBUG, "event: %s\n", __FUNCTION__); become_session(IO->CitContext); assert(IO->DNS.Query->PostDNS); diff --git a/citadel/event_client.h b/citadel/event_client.h index 6f2c6ad7a..2d5ab9861 100644 --- a/citadel/event_client.h +++ b/citadel/event_client.h @@ -100,6 +100,7 @@ typedef struct _evcurl_request_data /* DNS Related */ typedef struct __evcares_data { + ev_tstamp Start; ev_io recv_event, send_event; ev_timer timeout; /* timeout while requesting ips */ @@ -115,6 +116,9 @@ typedef struct __evcares_data { struct AsyncIO { long ID; + ev_tstamp Now; + ev_tstamp StartIO; + ev_tstamp StartDB; eNextState NextState; /* connection related */ diff --git a/citadel/modules/c-ares-dns/serv_c-ares-dns.c b/citadel/modules/c-ares-dns/serv_c-ares-dns.c index 8d433268d..d1b1a027e 100644 --- a/citadel/modules/c-ares-dns/serv_c-ares-dns.c +++ b/citadel/modules/c-ares-dns/serv_c-ares-dns.c @@ -433,6 +433,7 @@ int QueueQuery(ns_type Type, IO->DNS.Query = QueryParts; IO->DNS.Query->PostDNS = PostDNS; + IO->DNS.Start = IO->Now; InitC_ares_dns(IO); @@ -521,6 +522,7 @@ static void DNS_send_callback(struct ev_loop *loop, ev_io *watcher, int revents) { AsyncIO *IO = watcher->data; + IO->Now = ev_now(event_base); #ifdef DEBUG_CARES EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__); #endif @@ -533,6 +535,8 @@ static void DNS_recv_callback(struct ev_loop *loop, ev_io *watcher, int revents) { AsyncIO *IO = watcher->data; + IO->Now = ev_now(event_base); + #ifdef DEBUG_CARES EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__); #endif @@ -564,6 +568,7 @@ void SockStateCb(void *data, int sock, int read, int write) IO->DNS.SourcePort); } #endif + IO->Now = ev_now(event_base); if (read) { if ((IO->DNS.recv_event.fd != sock) && diff --git a/citadel/modules/eventclient/serv_eventclient.c b/citadel/modules/eventclient/serv_eventclient.c index dd3c4d403..ce5d7f041 100644 --- a/citadel/modules/eventclient/serv_eventclient.c +++ b/citadel/modules/eventclient/serv_eventclient.c @@ -121,6 +121,8 @@ gotstatus(int nnrun) curl_easy_strerror(sta)); IO = (AsyncIO *)chandle; + IO->Now = ev_now(event_base); + ev_io_stop(event_base, &IO->recv_event); ev_io_stop(event_base, &IO->send_event); @@ -248,6 +250,7 @@ gotdata(void *data, size_t size, size_t nmemb, void *cglobal) { { IO->HttpReq.ReplyData = NewStrBufPlain(NULL, SIZ); } + IO->Now = ev_now(event_base); return CurlFillStrBuf_callback(data, size, nmemb, @@ -306,6 +309,8 @@ gotwatchsock(CURL *easy, curl_multi_assign(mhnd, fd, IO); } + IO->Now = ev_now(event_base); + Action = ""; switch (action) { @@ -458,6 +463,7 @@ static void IOcurl_abort_shutdown_callback(struct ev_loop *loop, { CURLMcode msta; AsyncIO *IO = watcher->data; + IO->Now = ev_now(event_base); EV_syslog(LOG_DEBUG, "EVENT Curl: %s\n", __FUNCTION__); curl_slist_free_all(IO->HttpReq.headers); @@ -559,6 +565,7 @@ ev_async ExitEventLoop; static void QueueEventAddCallback(EV_P_ ev_async *w, int revents) { + ev_tstamp Now; HashList *q; void *v; HashPos*It; @@ -577,13 +584,17 @@ static void QueueEventAddCallback(EV_P_ ev_async *w, int revents) q = InboundEventQueues[1]; } pthread_mutex_unlock(&EventQueueMutex); - + Now = ev_now (event_base); It = GetNewHashPos(q, 0); while (GetNextHashPos(q, It, &len, &Key, &v)) { IOAddHandler *h = v; - if (h->IO->ID == 0) + if (h->IO->ID == 0) { h->IO->ID = EvIDSource++; + } + if (h->IO->StartIO == 0.0) + h->IO->StartIO = Now; + h->IO->Now = Now; h->EvAttch(h->IO); } DeleteHashPos(&It); @@ -687,6 +698,7 @@ extern void ShutDownDBCLient(AsyncIO *IO); static void DBQueueEventAddCallback(EV_P_ ev_async *w, int revents) { + ev_tstamp Now; HashList *q; void *v; HashPos *It; @@ -706,6 +718,7 @@ static void DBQueueEventAddCallback(EV_P_ ev_async *w, int revents) } pthread_mutex_unlock(&DBEventQueueMutex); + Now = ev_now (event_db); It = GetNewHashPos(q, 0); while (GetNextHashPos(q, It, &len, &Key, &v)) { @@ -713,6 +726,9 @@ static void DBQueueEventAddCallback(EV_P_ ev_async *w, int revents) eNextState rc; if (h->IO->ID == 0) h->IO->ID = EvIDSource++; + if (h->IO->StartDB == 0.0) + h->IO->StartDB = Now; + h->IO->Now = Now; rc = h->EvAttch(h->IO); switch (rc) { diff --git a/citadel/modules/smtp/serv_smtpeventclient.c b/citadel/modules/smtp/serv_smtpeventclient.c index 1698ab747..3037b0c0c 100644 --- a/citadel/modules/smtp/serv_smtpeventclient.c +++ b/citadel/modules/smtp/serv_smtpeventclient.c @@ -147,8 +147,9 @@ inline void FinalizeMessageSend_1(AsyncIO *IO) Status = "Delivery failed temporarily; will retry later."; EVS_syslog(LOG_INFO, - "SMTP: %s Recipient <%s> @ <%s> (%s) Statusmessage: %s\n", + "SMTP: %s Time[%fs] Recipient <%s> @ <%s> (%s) Statusmessage: %s\n", Status, + Msg->IO.Now - Msg->IO.StartIO, Msg->user, Msg->node, Msg->name, @@ -372,6 +373,9 @@ eNextState get_one_mx_host_ip_done(AsyncIO *IO) struct hostent *hostent; QueryCbDone(IO); + EVS_syslog(LOG_DEBUG, "SMTP: %s Time[%fs]\n", + __FUNCTION__, + IO->Now - IO->DNS.Start); hostent = Msg->HostLookup.VParsedDNSReply; if ((Msg->HostLookup.DNSStatus == ARES_SUCCESS) && @@ -467,7 +471,9 @@ eNextState smtp_resolve_mx_record_done(AsyncIO *IO) QueryCbDone(IO); - EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "SMTP: %s Time[%fs]\n", + __FUNCTION__, + IO->Now - IO->DNS.Start); pp = &Msg->Relay; while ((pp != NULL) && (*pp != NULL) && ((*pp)->Next != NULL)) -- 2.30.2