Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

F-stack kernel failing to track time properly #701

Closed
MrSonicMaster opened this issue Oct 13, 2022 · 2 comments
Closed

F-stack kernel failing to track time properly #701

MrSonicMaster opened this issue Oct 13, 2022 · 2 comments
Labels

Comments

@MrSonicMaster
Copy link

Steps to reproduce:

  1. clone latest code from github, build and install
  2. compile and run the attached code

Explanation 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.
Next logs show that if callout is registered via EVFILT_TIMER very close to boot time, it is able to trigger every 1 second.
After it updates/adds a timer further away from boot, however, it deviates a lot.
It 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.

Expected behavior: to track time properly regardless of when callout is added, and to correctly interpret the units specified.

I 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.

ADD/UPDATE TIMER
TRIGGER ident=1000000 data=1 fflags=0 since_last=45185.574288
TRIGGER ident=1000000 data=1 fflags=0 since_last=0.032788
TRIGGER ident=1000000 data=1 fflags=0 since_last=0.033428
TRIGGER ident=1000000 data=1 fflags=0 since_last=0.033980
TRIGGER ident=1000000 data=1 fflags=0 since_last=0.091014
TRIGGER ident=1000000 data=1 fflags=0 since_last=0.999392
TRIGGER ident=1000000 data=1 fflags=0 since_last=0.999392
TRIGGER ident=1000000 data=1 fflags=0 since_last=0.999391
TRIGGER ident=1000000 data=1 fflags=0 since_last=0.999392
TRIGGER ident=1000000 data=1 fflags=0 since_last=0.999391
ADD/UPDATE TIMER
TRIGGER ident=1000000 data=1 fflags=0 since_last=6.219578
TRIGGER ident=1000000 data=1 fflags=0 since_last=6.219578
TRIGGER ident=1000000 data=1 fflags=0 since_last=6.219578
TRIGGER ident=1000000 data=1 fflags=0 since_last=6.219579
TRIGGER ident=1000000 data=1 fflags=0 since_last=6.219578
TRIGGER ident=1000000 data=1 fflags=0 since_last=6.219577
TRIGGER ident=1000000 data=1 fflags=0 since_last=6.219586
TRIGGER ident=1000000 data=1 fflags=0 since_last=6.219569
TRIGGER ident=1000000 data=1 fflags=0 since_last=6.219578
TRIGGER ident=1000000 data=1 fflags=0 since_last=6.219579
ADD/UPDATE TIMER
TRIGGER ident=1000000 data=1 fflags=0 since_last=68.416336
TRIGGER ident=1000000 data=1 fflags=0 since_last=68.416337
TRIGGER ident=1000000 data=1 fflags=0 since_last=68.416335
...
#include <bits/time.h>
#include <errno.h>
#include <ff_api.h>
#include <generic/rte_cycles.h>
#include <stdio.h>
#include <string.h>
#include <time.h>
#include <unistd.h>

#define MAX_EVENTS 8 /* max events to return on a kevent() call */

static struct kevent events[MAX_EVENTS];
static int kq;

double get_ns() {
	struct timespec ts;
	clock_gettime(CLOCK_MONOTONIC, &ts);
	return 1e9L * ts.tv_sec + ts.tv_nsec;
}

static void add_or_update_timer() {
	printf("ADD/UPDATE TIMER\n");

	struct kevent kev;
	EV_SET(&kev, 1000000, EVFILT_TIMER, EV_ADD, NOTE_NSECONDS, 1, NULL);
	if (ff_kevent(kq, &kev, 1, NULL, 0, NULL) == -1) {
		printf("ff_kevent error:%d, %s\n", errno, strerror(errno));
	}
}

static int loop(void __attribute((unused)) * arg) {
	static uint32_t ntrigs = 0;
	static double last_ns = 0;

	int nevents = ff_kevent(kq, NULL, 0, events, MAX_EVENTS, NULL);
	if (nevents == -1) {
		perror("loop::ff_kevent()");
		return 0;
	}

	for (int i = 0; i < nevents; i++) {
		struct kevent event = events[i];

		if (event.filter == EVFILT_TIMER) {
			double ns = get_ns();
			printf("TRIGGER ident=%lu data=%ld fflags=%d since_last=%f\n", event.ident,
				   event.data, event.fflags, (ns - last_ns) / NS_PER_S);
			last_ns = ns;

			if (++ntrigs == 10) {
				add_or_update_timer();
				ntrigs = 0;
			}
		}
	}

	return 0;
}

int main(int argc, char *argv[]) {
	if (ff_init(argc, argv) != 0) {
		fprintf(stderr, "Failed to ff_init(%d): %s\n", errno, strerror(errno));
		return 1;
	}

	kq = ff_kqueue();
	if (kq == -1) {
		fprintf(stderr, "Failed to kqueue(%d): %s\n", errno, strerror(errno));
		return 0;
	}

	add_or_update_timer();

	ff_run(loop, NULL);

	return 1;
}
@MrSonicMaster
Copy link
Author

Ok, I was able to hack kern_event.c to do "fix" the bug. From my limited understanding of the codebase, it looks like like f-stack modified bsd callouts a good bit to accept 'ticks' as the argument instead of bintime, specifically wanting you to tell it 'run this callout N ticks from now.' i had to make kern_event hold true to that assumption by making all values absolute, rather than relative to sbinuptime(). Maybe you can continue with this and come up with a more proper fix.

@jfb8856606
Copy link
Contributor

I will check it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants