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

diff --git a/citadel/context.h b/citadel/context.h
index c2578036035f92bc73062aaf81566b8912a6a43e..08de75bb336a3b8d4b18161727c06cccbcdda53d 100644 (file)
--- 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 2e19b17b4ecaee4d9e41b355cf4faaeeda2889ae..d0e0fd9aefe9f20295a8827fda8fb5dabcf3f26b 100644 (file)
--- 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 6f2c6ad7ad28d264158889c19328ea3d4fb443ef..2d5ab986161d1a7a85de628b766d2dec5f2fec29 100644 (file)
--- 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 8d433268dc0e6c56cc4292e9a263ac40e6259d02..d1b1a027e5f86d2ac33acdad19115058585d4b69 100644 (file)
--- 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 dd3c4d403bb1fc1c8f66d7b4199d2323e38fcd31..ce5d7f0412c12246e8663e6d2025b992cd6992f7 100644 (file)
--- 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 1698ab74773c1886d7152a3e6b088f1594b12abc..3037b0c0c65e39cb7f7a7fecb4c843365f2800a2 100644 (file)
--- 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))