{"id":293,"date":"2015-10-16T08:17:51","date_gmt":"2015-10-16T08:17:51","guid":{"rendered":"https:\/\/projects.lsv.ens-paris-saclay.fr\/orchidsdev\/?p=293"},"modified":"2015-10-16T08:18:07","modified_gmt":"2015-10-16T08:18:07","slug":"gettimeofday-and-ctx-cur_loop_time","status":"publish","type":"post","link":"https:\/\/projects.lsv.ens-paris-saclay.fr\/orchidsdev\/?p=293","title":{"rendered":"gettimeofday() and ctx->cur_loop_time"},"content":{"rendered":"

The event manager keeps track of the current time in the cur_loop_time<\/code> field of the Orchids context. When you want to reschedule an event to take place in, say, 5 seconds, it is tempting to write:<\/p>\n

  heap_entry_t *he;\r\n\r\n  \/* ... *\/\r\n  he->date = ctx->cur_loop_time + 5;\r\n  register_rtaction(ctx, he);\r\n<\/pre>\n
This post explains why this is a bad idea, and how it should be done.<\/p>\n
In brief, instead of using ctx->cur_loop_time<\/code>, where ctx<\/code> is your Orchids context, you should call gettimeofday()<\/code>. This is not that slower. And this will solve an issue caused by your computer going to sleep (mostly laptops, but also virtualized sessions).<\/p>\n
All right, so what is happening? The main Orchids loop is the function\u00a0event_dispatcher_main_loop()<\/code><\/a>. \u00a0It first calls gettimeofday()<\/code> to obtain the current time, and stores it into ctx->cur_loop_time<\/code>. Then, it looks for rtcallback<\/code>s to handle before it calls select()<\/code>. This rtcallback<\/code> handling appears to be instantaneous: a small loop, calling functions that do not wait on any external event. So not much time will elapse and the current time of day will remain close to ctx->cur_loop_time<\/code>;perhaps a few clock cycles, right?<\/p>\n
In fact, no. If, in the middle of that, the computer goes to sleep mode, and is reawakened, say, one hour later, then ctx->cur_loop_time<\/code> will be lagging by 3600 seconds behind the actual time.<\/p>\n
As a consequence, imagine a task that is scheduled to take place every\u00a05 seconds (this once happened with the save mechanism). When the\u00a0computer is reawakened, it will then do that task 3600\/5 = 720 times. \u00a0This will take 100% cpu time while it is catching up, causing some behavior that will look strange to the outside observer.<\/p>\n
So, instead, call gettimeofday()<\/code>. To illustrate this, look at the following rtcallback<\/code>, using by mod_textfile<\/code> to poll files every cfg->poll_period<\/code> seconds:<\/p>\n
static int rtaction_read_textfiles(orchids_t *ctx, heap_entry_t *he)\r\n{\r\n  mod_entry_t *mod;\r\n  textfile_config_t *cfg;\r\n  char\t      eof;\r\n\r\n  mod = (mod_entry_t *)he->data;\r\n  cfg = (textfile_config_t *)mod->config;\r\n  eof = textfile_callback(ctx, mod, NULL);\r\n  gettimeofday(&he->date, NULL);\r\n  \/* It is a bad idea to 'optimize' the above by writing instead:\r\n     he->date = ctx->cur_loop_time;\r\n  *\/\r\n  if (eof)\r\n    he->date.tv_sec += cfg->poll_period;\r\n  register_rtaction(ctx, he);\r\n  return 0;\r\n}\r\n<\/pre>\n
Calling gettimeofday()<\/code> is actually fast, too. On modern architectures, this will not make any system call, most of the time.<\/p>\n
I have seen a timing of 54 clock cycles reported here<\/a> (read, 16 oct. 2015).<\/p>\n
With the code that follows, on the Mac OS X 10.9.2 I am using\u00a0while writing this, 100 million calls to gettimeofday()<\/code>\u00a0takes 5 seconds; in other words, one call takes about 50 ns.  time()<\/code>, by the way, is slower: 100 million calls takes 22 seconds, namely, one call to time()<\/code> takes 220 ns.<\/p>\n
#include \r\n#include \r\n#include <sys\/time.h>\r\n\r\nvoid printTime(time_t now)\r\n{\r\n    struct tm  tstruct;\r\n    char       buf[80];\r\n    tstruct = *localtime(&now);\r\n    strftime(buf, sizeof(buf), \"%Y-%m-%d.%X\", &tstruct);\r\n    printf (\"%s\\n\", buf);\r\n}\r\n\r\nint main(void)\r\n{\r\n   struct timeval tv;\r\n   time_t tm;\r\n\r\n   gettimeofday(&tv,NULL);\r\n   printTime((time_t)tv.tv_sec);\r\n   for(int i=0; i<100000000; i++)\r\n        gettimeofday(&tv,NULL);\r\n   gettimeofday(&tv,NULL);\r\n   printTime((time_t)tv.tv_sec);\r\n\r\n   printTime(time(NULL));\r\n   for(int i=0; i<100000000; i++)\r\n        tm=time(NULL);\r\n   printTime(time(NULL));\r\n\r\n   return 0;\r\n}\r\n<\/pre>\n","protected":false},"excerpt":{"rendered":"
The event manager keeps track of the current time in the cur_loop_time field of the Orchids context. When you want to reschedule an event to take place in, say, 5 seconds, it is tempting to write: heap_entry_t *he; \/* … *\/ he->date = ctx->cur_loop_time + 5; register_rtaction(ctx, he); This post explains why this is a […]<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"closed","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[7,8],"tags":[],"class_list":["post-293","post","type-post","status-publish","format-standard","hentry","category-bugs-mean-bugs-and-c","category-event-management"],"_links":{"self":[{"href":"https:\/\/projects.lsv.ens-paris-saclay.fr\/orchidsdev\/index.php?rest_route=\/wp\/v2\/posts\/293","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/projects.lsv.ens-paris-saclay.fr\/orchidsdev\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/projects.lsv.ens-paris-saclay.fr\/orchidsdev\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/projects.lsv.ens-paris-saclay.fr\/orchidsdev\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/projects.lsv.ens-paris-saclay.fr\/orchidsdev\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=293"}],"version-history":[{"count":2,"href":"https:\/\/projects.lsv.ens-paris-saclay.fr\/orchidsdev\/index.php?rest_route=\/wp\/v2\/posts\/293\/revisions"}],"predecessor-version":[{"id":295,"href":"https:\/\/projects.lsv.ens-paris-saclay.fr\/orchidsdev\/index.php?rest_route=\/wp\/v2\/posts\/293\/revisions\/295"}],"wp:attachment":[{"href":"https:\/\/projects.lsv.ens-paris-saclay.fr\/orchidsdev\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=293"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/projects.lsv.ens-paris-saclay.fr\/orchidsdev\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=293"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/projects.lsv.ens-paris-saclay.fr\/orchidsdev\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=293"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}