René's URL Explorer Experiment

{"@context":"https://schema.org","@type":"DiscussionForumPosting","headline":"F-stack kernel failing to track time properly","articleBody":"Steps to reproduce:\r\n1. clone latest code from github, build and install\r\n2. compile and run the attached code\r\n\r\nExplanation of issue being shown: Very first log value is from me being lazy in the sample code, logs after that are during boot, multiple callouts get delayed and batched so they are very close to each other. something to do with freebsd.expire being too far ahead for first trigger, increasing boot.hz seems to decrease the delay but besides the point that's a small issue.  \r\nNext logs show that if callout is registered via EVFILT_TIMER very close to boot time, it is able to trigger every 1 second.\r\nAfter it updates/adds a timer further away from boot, however, it deviates a lot.\r\nIt also for some reason has its units way off - I had to ask it to interpret my argument as 1 nanosecond(s) for it to track 1 second.\r\n\r\nExpected behavior: to track time properly regardless of when callout is added, and to correctly interpret the units specified.\r\n\r\nI tried to debug a bit, but could not figure out a solution - seems like maybe something to do with sbinuptime() and tick_sbt not matching. I am unsure if this bug is limited to EVFILT_TIMER or how many other subsystems are affected, clearly it can track time under some circumstances.\r\n\r\n```\r\nADD/UPDATE TIMER\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=45185.574288\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=0.032788\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=0.033428\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=0.033980\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=0.091014\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=0.999392\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=0.999392\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=0.999391\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=0.999392\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=0.999391\r\nADD/UPDATE TIMER\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=6.219578\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=6.219578\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=6.219578\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=6.219579\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=6.219578\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=6.219577\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=6.219586\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=6.219569\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=6.219578\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=6.219579\r\nADD/UPDATE TIMER\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=68.416336\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=68.416337\r\nTRIGGER ident=1000000 data=1 fflags=0 since_last=68.416335\r\n...\r\n```\r\n\r\n```c\r\n#include \u003cbits/time.h\u003e\r\n#include \u003cerrno.h\u003e\r\n#include \u003cff_api.h\u003e\r\n#include \u003cgeneric/rte_cycles.h\u003e\r\n#include \u003cstdio.h\u003e\r\n#include \u003cstring.h\u003e\r\n#include \u003ctime.h\u003e\r\n#include \u003cunistd.h\u003e\r\n\r\n#define MAX_EVENTS 8 /* max events to return on a kevent() call */\r\n\r\nstatic struct kevent events[MAX_EVENTS];\r\nstatic int kq;\r\n\r\ndouble get_ns() {\r\n\tstruct timespec ts;\r\n\tclock_gettime(CLOCK_MONOTONIC, \u0026ts);\r\n\treturn 1e9L * ts.tv_sec + ts.tv_nsec;\r\n}\r\n\r\nstatic void add_or_update_timer() {\r\n\tprintf(\"ADD/UPDATE TIMER\\n\");\r\n\r\n\tstruct kevent kev;\r\n\tEV_SET(\u0026kev, 1000000, EVFILT_TIMER, EV_ADD, NOTE_NSECONDS, 1, NULL);\r\n\tif (ff_kevent(kq, \u0026kev, 1, NULL, 0, NULL) == -1) {\r\n\t\tprintf(\"ff_kevent error:%d, %s\\n\", errno, strerror(errno));\r\n\t}\r\n}\r\n\r\nstatic int loop(void __attribute((unused)) * arg) {\r\n\tstatic uint32_t ntrigs = 0;\r\n\tstatic double last_ns = 0;\r\n\r\n\tint nevents = ff_kevent(kq, NULL, 0, events, MAX_EVENTS, NULL);\r\n\tif (nevents == -1) {\r\n\t\tperror(\"loop::ff_kevent()\");\r\n\t\treturn 0;\r\n\t}\r\n\r\n\tfor (int i = 0; i \u003c nevents; i++) {\r\n\t\tstruct kevent event = events[i];\r\n\r\n\t\tif (event.filter == EVFILT_TIMER) {\r\n\t\t\tdouble ns = get_ns();\r\n\t\t\tprintf(\"TRIGGER ident=%lu data=%ld fflags=%d since_last=%f\\n\", event.ident,\r\n\t\t\t\t   event.data, event.fflags, (ns - last_ns) / NS_PER_S);\r\n\t\t\tlast_ns = ns;\r\n\r\n\t\t\tif (++ntrigs == 10) {\r\n\t\t\t\tadd_or_update_timer();\r\n\t\t\t\tntrigs = 0;\r\n\t\t\t}\r\n\t\t}\r\n\t}\r\n\r\n\treturn 0;\r\n}\r\n\r\nint main(int argc, char *argv[]) {\r\n\tif (ff_init(argc, argv) != 0) {\r\n\t\tfprintf(stderr, \"Failed to ff_init(%d): %s\\n\", errno, strerror(errno));\r\n\t\treturn 1;\r\n\t}\r\n\r\n\tkq = ff_kqueue();\r\n\tif (kq == -1) {\r\n\t\tfprintf(stderr, \"Failed to kqueue(%d): %s\\n\", errno, strerror(errno));\r\n\t\treturn 0;\r\n\t}\r\n\r\n\tadd_or_update_timer();\r\n\r\n\tff_run(loop, NULL);\r\n\r\n\treturn 1;\r\n}\r\n```","author":{"url":"https://github.com/MrSonicMaster","@type":"Person","name":"MrSonicMaster"},"datePublished":"2022-10-13T07:12:14.000Z","interactionStatistic":{"@type":"InteractionCounter","interactionType":"https://schema.org/CommentAction","userInteractionCount":2},"url":"https://github.com/701/f-stack/issues/701"}