tools/tests/darwintests/kevent_continuous_time.c

   1 #include <stdio.h>
   2 #include <unistd.h>
   3
   4 #include <mach/mach.h>
   5 #include <mach/mach_time.h>
   6 #include <sys/time.h>
   7 #include <spawn.h>
   8 #include <sys/wait.h>
   9 #include <stdio.h>
  10 #include <unistd.h>
  11 #include <stdlib.h>
  12 #include <time.h>
  13 #include <errno.h>
  14 #include <sys/event.h>
  15
  16 #include <darwintest.h>
  17
  18 extern char **environ;
  19
  20 static mach_timebase_info_data_t tb_info;
  21 static const uint64_t one_mil = 1000LL*1000LL;
  22
  23 #define tick_to_ns(ticks) (((ticks) * tb_info.numer) / (tb_info.denom))
  24 #define tick_to_ms(ticks) (tick_to_ns(ticks)/one_mil)
  25
  26 #define ns_to_tick(ns) ((ns) * tb_info.denom / tb_info.numer)
  27 #define ms_to_tick(ms) (ns_to_tick((ms) * one_mil))
  28
  29 static uint64_t time_delta_ms(void){
  30         uint64_t abs_now = mach_absolute_time();
  31         uint64_t cnt_now = mach_continuous_time();;
  32         return tick_to_ms(cnt_now) - tick_to_ms(abs_now);
  33 }
  34
  35 static int run_sleep_tests = 0;
  36
  37 static int trigger_sleep(int for_secs) {
  38         if(!run_sleep_tests) return 0;
  39
  40         // sleep for 1 seconds each iteration
  41         char buf[10];
  42         snprintf(buf, 10, "%d", for_secs);
  43
  44         T_LOG("Sleepeing for %s seconds...", buf);
  45
  46         int spawn_ret, pid;
  47         char *const pmset1_args[] = {"/usr/bin/pmset", "relative", "wake", buf, NULL};
  48         T_ASSERT_POSIX_ZERO((spawn_ret = posix_spawn(&pid, pmset1_args[0], NULL, NULL, pmset1_args, environ)), NULL);
  49
  50         T_ASSERT_EQ(waitpid(pid, &spawn_ret, 0), pid, NULL);
  51         T_ASSERT_EQ(spawn_ret, 0, NULL);
  52
  53         char *const pmset2_args[] = {"/usr/bin/pmset", "sleepnow", NULL};
  54         T_ASSERT_POSIX_ZERO((spawn_ret = posix_spawn(&pid, pmset2_args[0], NULL, NULL, pmset2_args, environ)), NULL);
  55
  56         T_ASSERT_EQ(waitpid(pid, &spawn_ret, 0), pid, NULL);
  57         T_ASSERT_EQ(spawn_ret, 0, NULL);
  58
  59         return 0;
  60 }
  61
  62 // waits up to 30 seconds for system to sleep
  63 // returns number of seconds it took for sleep to be entered
  64 // or -1 if sleep wasn't accomplished
  65 static int wait_for_sleep() {
  66         if(!run_sleep_tests) return 0;
  67
  68         uint64_t before_diff = time_delta_ms();
  69
  70         for(int i = 0; i < 30; i++) {
  71                 uint64_t after_diff = time_delta_ms();
  72
  73                 // on OSX, there's enough latency between calls to MCT and MAT
  74                 // when the system is going down for sleep for values to diverge a few ms
  75                 if(llabs((int64_t)before_diff - (int64_t)after_diff) > 2) {
  76                         return i + 1;
  77                 }
  78
  79                 sleep(1);
  80                 T_LOG("waited %d seconds for sleep...", i+1);
  81         }
  82         return -1;
  83 }
  84
  85 T_DECL(kevent_continuous_time_periodic_tick, "kevent(EVFILT_TIMER with NOTE_MACH_CONTINUOUS_TIME)", T_META_LTEPHASE(LTE_POSTINIT)){
  86         mach_timebase_info(&tb_info);
  87         int kq;
  88         T_ASSERT_POSIX_SUCCESS((kq = kqueue()), NULL);
  89
  90         struct kevent64_s change = {0};
  91         EV_SET64(&change, 1, EVFILT_TIMER, EV_ADD, NOTE_SECONDS | NOTE_MACH_CONTINUOUS_TIME, 4, 0, 0, 0);
  92         T_LOG("EV_SET(&change, 1, EVFILT_TIMER, EV_ADD, NOTE_SECONDS | NOTE_MACH_CONTINUOUS_TIME, 4, 0, 0, 0);");
  93
  94         T_ASSERT_POSIX_ZERO(kevent64(kq, &change, 1, NULL, 0, 0, NULL), NULL);
  95
  96         uint64_t abs_then = mach_absolute_time();
  97         uint64_t cnt_then = mach_continuous_time();;
  98
  99         trigger_sleep(1);
 100         int sleep_secs = wait_for_sleep();
 101
 102         struct kevent64_s event = {0};
 103         T_WITH_ERRNO; T_ASSERT_EQ(kevent64(kq, NULL, 0, &event, 1, 0, NULL), 1, "kevent() should have returned one event");
 104         T_LOG("event = {.ident = %llx, .filter = %d, .flags = %d, .fflags = %d, .data = %lld, .udata = %lld}", event.ident, event.filter, event.flags, event.fflags, event.data, event.udata);
 105         T_ASSERT_EQ(event.flags & EV_ERROR, 0, "event should not have EV_ERROR set: %s", event.flags & EV_ERROR ? strerror((int)event.data) : "no error");
 106
 107         uint64_t abs_now = mach_absolute_time();
 108         uint64_t cnt_now = mach_continuous_time();;
 109         uint64_t ct_ms_progressed = tick_to_ms(cnt_now - cnt_then);
 110         uint64_t ab_ms_progressed = tick_to_ms(abs_now - abs_then);
 111
 112         T_LOG("ct progressed %llu ms, abs progressed %llu ms", ct_ms_progressed, tick_to_ms(abs_now - abs_then));
 113
 114         if (run_sleep_tests) {
 115                 T_ASSERT_GT(llabs((int64_t)ct_ms_progressed - (int64_t)ab_ms_progressed), 500LL, "should have > 500ms difference between MCT and MAT");
 116         } else {
 117                 T_ASSERT_LT(llabs((int64_t)ct_ms_progressed - (int64_t)ab_ms_progressed), 10LL, "should have < 10ms difference between MCT and MAT");
 118         }
 119
 120         if (sleep_secs < 4) {
 121                 T_ASSERT_LT(llabs((int64_t)ct_ms_progressed - 4000), 100LL, "mach_continuous_time should progress ~4 seconds (+/- 100ms) between sleeps");
 122         }
 123
 124         sleep(1);
 125
 126         EV_SET64(&change, 1, EVFILT_TIMER, EV_DELETE, 0, 0, 0, 0, 0);
 127         T_LOG("EV_SET(&change, 1, EVFILT_TIMER, EV_DELETE, 0, 0, 0);");
 128         T_ASSERT_EQ(kevent64(kq, &change, 1, NULL, 0, 0, NULL), 0, NULL);
 129
 130         T_ASSERT_POSIX_ZERO(close(kq), NULL);
 131 }
 132
 133 T_DECL(kevent_continuous_time_absolute, "kevent(EVFILT_TIMER with NOTE_MACH_CONTINUOUS_TIME and NOTE_ABSOLUTE)", T_META_LTEPHASE(LTE_POSTINIT)){
 134         mach_timebase_info(&tb_info);
 135
 136         int kq;
 137         T_ASSERT_POSIX_SUCCESS((kq = kqueue()), NULL);
 138
 139         struct timeval tv;
 140         gettimeofday(&tv, NULL);
 141         uint64_t nowus   = (uint64_t)tv.tv_sec * USEC_PER_SEC + (uint64_t)tv.tv_usec;
 142         uint64_t fire_at = (3*USEC_PER_SEC) + nowus;
 143
 144         uint64_t cnt_now = mach_continuous_time();
 145         uint64_t cnt_then = cnt_now + ms_to_tick(3000);
 146
 147         T_LOG("currently is %llu, firing at %llu", nowus, fire_at);
 148
 149         struct kevent64_s change = {0};
 150         EV_SET64(&change, 2, EVFILT_TIMER, EV_ADD, NOTE_MACH_CONTINUOUS_TIME | NOTE_ABSOLUTE | NOTE_USECONDS, fire_at, 0, 0, 0);
 151         T_LOG("EV_SET(&change, 2, EVFILT_TIMER, EV_ADD, NOTE_MACH_CONTINUOUS_TIME | NOTE_ABSOLUTE | NOTE_USECONDS, fire_at, 0);");
 152
 153         T_ASSERT_EQ(kevent64(kq, &change, 1, NULL, 0, 0, NULL), 0, NULL);
 154
 155         T_LOG("testing NOTE_MACH_CONTINUOUS_TIME | NOTE_ABSOLUTE between sleep");
 156
 157         trigger_sleep(1);
 158
 159         struct timespec timeout = {
 160                 .tv_sec = 10,
 161                 .tv_nsec = 0
 162         };
 163         struct kevent64_s event = {0};
 164         T_ASSERT_EQ(kevent64(kq, NULL, 0, &event, 1, 0, &timeout), 1, "kevent() should have returned one event");
 165         T_LOG("event = {.ident = %llx, .filter = %d, .flags = %d, .fflags = %d, .data = %lld, .udata = %lld}", event.ident, event.filter, event.flags, event.fflags, event.data, event.udata);
 166         T_ASSERT_EQ(event.flags & EV_ERROR, 0, "event should not have EV_ERROR set: %s", event.flags & EV_ERROR ? strerror((int)event.data) : "no error");
 167
 168         uint64_t elapsed_ms = tick_to_ms(mach_continuous_time() - cnt_now);
 169         int64_t missed_by  = tick_to_ns((int64_t)mach_continuous_time() - (int64_t)cnt_then) / 1000000;
 170
 171         // ~1/2 second is about as good as we'll get
 172         T_ASSERT_LT(llabs(missed_by), 500LL, "timer should pop 3 sec in the future, popped after %lldms", elapsed_ms);
 173
 174         T_ASSERT_EQ(event.data, 1LL, NULL);
 175
 176         T_ASSERT_EQ(event.ident, 2ULL, NULL);
 177
 178         // try getting a periodic tick out of kq
 179         T_ASSERT_EQ(kevent64(kq, NULL, 0, &event, 1, 0, &timeout), 0, NULL);
 180         T_ASSERT_EQ(event.flags & EV_ERROR, 0, "event should not have EV_ERROR set: %s", event.flags & EV_ERROR ? strerror((int)event.data) : "no error");
 181
 182         T_ASSERT_POSIX_ZERO(close(kq), NULL);
 183 }
 184
 185 T_DECL(kevent_continuous_time_pops, "kevent(EVFILT_TIMER with NOTE_MACH_CONTINUOUS_TIME with multiple pops)", T_META_LTEPHASE(LTE_POSTINIT)){
 186         // have to throttle rate at which pmset is called
 187         sleep(2);
 188
 189         mach_timebase_info(&tb_info);
 190
 191         int kq;
 192         T_ASSERT_POSIX_SUCCESS((kq = kqueue()), NULL);
 193
 194         // test that periodic ticks accumulate while asleep
 195         struct kevent64_s change = {0};
 196         EV_SET64(&change, 3, EVFILT_TIMER, EV_ADD, NOTE_MACH_CONTINUOUS_TIME, 100, 0, 0, 0); // tick every 100 ms
 197         T_LOG("EV_SET(&change, 3, EVFILT_TIMER, EV_ADD, NOTE_MACH_CONTINUOUS_TIME, 100, 0);");
 198
 199         // wait for first pop, then sleep
 200         T_ASSERT_EQ(kevent64(kq, &change, 1, NULL, 0, 0, NULL), 0, NULL);
 201
 202         struct kevent64_s event = {0};
 203         T_ASSERT_EQ(kevent64(kq, NULL, 0, &event, 1, 0, NULL), 1, "kevent() should have returned one event");
 204         T_LOG("event = {.ident = %llx, .filter = %d, .flags = %d, .fflags = %d, .data = %lld, .udata = %llu}", event.ident, event.filter, event.flags, event.fflags, event.data, event.udata);
 205         T_ASSERT_EQ(event.flags & EV_ERROR, 0, "should not have EV_ERROR set: %s", event.flags & EV_ERROR ? strerror((int)event.data) : "no error");
 206         T_ASSERT_EQ(event.ident, 3ULL, NULL);
 207
 208         uint64_t cnt_then = mach_continuous_time();
 209         trigger_sleep(2);
 210
 211         int sleep_secs = 0;
 212         if(run_sleep_tests) {
 213                 sleep_secs = wait_for_sleep();
 214         }
 215         else {
 216                 // simulate 2 seconds of system "sleep"
 217                 sleep(2);
 218         }
 219
 220         uint64_t cnt_now = mach_continuous_time();
 221
 222         uint64_t ms_elapsed = tick_to_ms(cnt_now - cnt_then);
 223         if(run_sleep_tests) {
 224                 T_ASSERT_LT(llabs((int64_t)ms_elapsed - 2000LL), 500LL, "slept for %llums, expected 2000ms (astris is connected?)", ms_elapsed);
 225         }
 226
 227         T_ASSERT_EQ(kevent64(kq, NULL, 0, &event, 1, 0, NULL), 1, "kevent() should have returned one event");
 228         T_LOG("event = {.ident = %llx, .filter = %d, .flags = %d, .fflags = %d, .data = %lld, .udata = %llu}", event.ident, event.filter, event.flags, event.fflags, event.data, event.udata);
 229         T_ASSERT_EQ(event.ident, 3ULL, NULL);
 230
 231         uint64_t expected_pops = ms_elapsed / 100;
 232         uint64_t got_pops      = (uint64_t)event.data;
 233
 234         T_ASSERT_GE(got_pops, expected_pops - 1, "tracking pops while asleep");
 235         T_ASSERT_POSIX_ZERO(close(kq), NULL);
 236 }