Greetings,
I'm experiencing what appears to be a minimum clock resolution issue in
using clock_gettime() on a PandaBoard ES running ubuntu.
*> uname -r*
3.1.1-8-linaro-lt-omap
*> cat /proc/version*
Linux version 3.1.1-8-linaro-lt-omap (buildd@diphda) (gcc version
4.6.1 (Ubuntu/Linaro 4.6.1-9ubuntu3) )
#8~lt~ci~20120118001257+025756-Ubuntu SMP PREEMPT Thu Jan 19 09:
I'm using clock_gettime() (and have tried gettimeofday()) to compute the
elapsed time around roughly 15ms of computation (image processing).
While the computed time is stable on my x86_64 machine, it is not on my
PandaBoard ES. I have tried various clocks (e.g. CLOCK_REALTIME), but
the issue remains. No error codes are returned by clock_gettime().
The result on my x86_64 machine looks like this:
*elapsed (s) elapsed (ns) elapsed (us) time
(after) time (before)*
0s 532260ns *532us* (t1: 73741s
92573265ns) (t0: 73741s 92041005ns)
0s 544413ns *544us* (t1: 73741s
109390136ns) (t0: 73741s 108845723ns)
0s 529328ns *529us* (t1: 73741s
126024860ns) (t0: 73741s 125495532ns)
A: 1.7s in total. *0.536ms* on average.
If I move over to my PandaBoard ES, I calculate elapsed times of 0us on
some iterations.
*elapsed (s) elapsed (ns) elapsed (us) time
(after) time (before)*
0s 0ns *0us* (t1: 269529s
192626951ns) (t0: 269529s 192626951ns)
0s 0ns *0us* (t1: 269529s 215606688ns)
(t0: 269529s 215606688ns)
0s 2655030ns *2655us* (t1: 269529s 252349852ns) (t0:
269529s 249694822ns)
0s 2593994ns *2593us* (t1: 269529s 286163328ns) (t0:
269529s 283569334ns)
0s 30518ns *30us* (t1: 269529s 317657469ns) (t0:
269529s 317626951ns)
If I crank up the amount of work done between the time calls
(timetest.c:18: inneriters = 1e7;) such that the timed loop takes around
72ms, the timing results seem accurate and none of the intermediate
calculations result in a 0us elapsed time. If I reduce it to around
10-25ms (inneriters=1e6), I get occasional 0us elapsed times. Around 2ms
(inneriters=1e5), most results measure an elapsed time of 0us.
I'm trying to optimize image processing functions, which take on the
order of 2-15ms to process. Am I stuck with this timing resolution? I
want to be careful to not omit issues like cache performance when
timing, as I might if I repeatedly process an image to average the
results. Currently, that seems like the best option.
Source code and makefile attached, as well as /proc/timer_list
Is this a property of the hardware, or might it be a bug?
Thanks,
Andrew
GCC = gcc -g -std=gnu99
all: timetest
timetest: timestamp.o timetest.o
gcc -o $@ timestamp.o timetest.o -lrt
%.o: %.s
$(GCC) -O0 -c $<
%.s: %.c
$(GCC) -O0 -S $<
clean:
rm -f *~ timetest *.o *.s
.PHONY: clean
#include "timestamp.h"
timespec_t timestamp_now()
{
timespec_t ts; // tv_sec and tv_nsec fields
// clock_gettime() version
{
clockid_t id = CLOCK_MONOTONIC_RAW;
int res = clock_gettime(id, &ts);
if (res != 0)
printf("clock_gettime() returned an error code! %d\n", res);
}
// gettimeofday() version
//{
// struct timeval tv;
// gettimeofday (&tv, NULL);
// // convert
// ts.tv_sec = tv.tv_sec;
// ts.tv_nsec = tv.tv_usec * 1E3;
//}
return ts;
}
int32_t get_dt(timespec_t t1, timespec_t t0)
{
// seconds
__time_t ds = t1.tv_sec - t0.tv_sec;
// nanoseconds
long int dns = t1.tv_nsec - t0.tv_nsec;
// microseconds
int32_t dt = (ds * 1E6) + (dns * 1E-3);
printf("%6ds %12dns %12dus (t1: %6ds %12dns) (t0: %6ds %12dns)\n",
ds, dns, dt,
t1.tv_sec, t1.tv_nsec,
t0.tv_sec, t0.tv_nsec);
return dt;
}
#ifndef TIMESTAMP_H
#define TIMESTAMP_H
#include <stdlib.h>
#include <stdio.h>
#include <stdint.h>
#include <assert.h>
#include <time.h>
#include <sys/time.h>
typedef struct timespec timespec_t;
timespec_t timestamp_now();
int32_t get_dt(timespec_t t1, timespec_t t0);
#endif
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include "timestamp.h"
int work(int iter)
{
int a = 0;
for (int foo=0; foo < iter; foo++)
a += foo;
return a;
}
int main(int argc, char *argv[])
{
int outeriters = 100;
int inneriters = 10000000;
for (int iter=0; ; iter++) {
////////////////////////////////////////////////////////////////////////////////
{
int32_t total = 0;
timespec_t outer_t0 = timestamp_now();
for (int i=0; i < outeriters; i++) {
timespec_t t0 = timestamp_now();
int a = work(inneriters);
timespec_t t1 = timestamp_now();
int32_t dt = get_dt(t1, t0);
total += dt;
usleep(16000);
}
timespec_t outer_t1 = timestamp_now();
int32_t outer_dt = get_dt(outer_t1, outer_t0);
printf("A: %3.1fs in total. %8.3fms on average.\n",
outer_dt * 1.0E-6,
total / outeriters * 1.0E-3);
}
}
}
Timer List Version: v0.6
HRTIMER_MAX_CLOCK_BASES: 3
now at 272073099517824 nsecs
cpu: 0
clock 0:
.base: 00000000
.index: 0
.resolution: 1 nsecs
.get_time: ktime_get
.offset: 0 nsecs
active timers:
#0: <00000000>, tick_sched_timer, S:01, hrtimer_start_range_ns, swapper/0
# expires at 272073101562500-272073101562500 nsecs [in 2044676 to 2044676
nsecs]
#1: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, compiz/2136
# expires at 272073130037843-272073130097843 nsecs [in 30520019 to 30580019
nsecs]
#2: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns,
update-manager/2287
# expires at 272074090667727-272074095667727 nsecs [in 991149903 to 996149903
nsecs]
#3: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns,
gnome-settings-/2070
# expires at 272074097564700-272074098564669 nsecs [in 998046876 to 999046845
nsecs]
#4: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, nautilus/2159
# expires at 272074098114016-272074099114016 nsecs [in 998596192 to 999596192
nsecs]
#5: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns,
accounts-daemon/1845
# expires at 272076000455568-272076004451415 nsecs [in 2900937744 to
2904933591 nsecs]
#6: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns,
console-kit-dae/1706
# expires at 272076000744143-272076029807112 nsecs [in 2901226319 to
2930289288 nsecs]
#7: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, rtkit-daemon/2193
# expires at 272074290497480-272076790497480 nsecs [in 1190979656 to
3690979656 nsecs]
#8: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, rtkit-daemon/2194
# expires at 272079290497480-272079290497480 nsecs [in 6190979656 to
6190979656 nsecs]
#9: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, ssh-agent/2051
# expires at 272082669372562-272082679372562 nsecs [in 9569854738 to
9579854738 nsecs]
#10: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, rsyslogd/1445
# expires at 272084191802980-272084221802980 nsecs [in 11092285156 to
11122285156 nsecs]
#11: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns,
gnome-screensav/2192
# expires at 272093772472644-272093797927644 nsecs [in 20672954820 to
20698409820 nsecs]
#12: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, gconfd-2/2077
# expires at 272099772078175-272099802072175 nsecs [in 26672560351 to
26702554351 nsecs]
#13: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns,
avahi-daemon/1492
# expires at 272215547723390-272215647723390 nsecs [in 142448205566 to
142548205566 nsecs]
#14: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns,
udisks-daemon/2158
# expires at 273746000990480-273746100990480 nsecs [in 1672901472656 to
1673001472656 nsecs]
#15: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, dhclient/1877
# expires at 288948219330705-288948319330705 nsecs [in 16875119812881 to
16875219812881 nsecs]
clock 1:
.base: 00000000
.index: 1
.resolution: 1 nsecs
.get_time: ktime_get_real
.offset: 1328382209780821967 nsecs
active timers:
clock 2:
.base: 00000000
.index: 2
.resolution: 1 nsecs
.get_time: ktime_get_boottime
.offset: 0 nsecs
active timers:
.expires_next : 272073101562500 nsecs
.hres_active : 1
.nr_events : 8492165
.nr_retries : 44620
.nr_hangs : 0
.max_hang_time : 0 nsecs
.nohz_mode : 2
.idle_tick : 272073078125000 nsecs
.tick_stopped : 0
.idle_jiffies : 34786953
.idle_calls : 13914835
.idle_sleeps : 10381583
.idle_entrytime : 272073098114016 nsecs
.idle_waketime : 272073079345705 nsecs
.idle_exittime : 272073079742434 nsecs
.idle_sleeptime : 266228859853210 nsecs
.iowait_sleeptime: 1715169393760 nsecs
.last_jiffies : 34786956
.next_jiffies : 34786957
.idle_expires : 272073085937500 nsecs
jiffies: 34786956
cpu: 1
clock 0:
.base: 00000000
.index: 0
.resolution: 1 nsecs
.get_time: ktime_get
.offset: 0 nsecs
active timers:
#0: <00000000>, tick_sched_timer, S:01, hrtimer_start_range_ns, swapper/0
# expires at 272073101562500-272073101562500 nsecs [in 2044676 to 2044676
nsecs]
#1: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns,
update-notifier/2248
# expires at 272075990722723-272075995722723 nsecs [in 2891204899 to
2896204899 nsecs]
#2: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, cron/1543
# expires at 272131329132084-272131329182084 nsecs [in 58229614260 to
58229664260 nsecs]
#3: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns,
zeitgeist-daemo/2215
# expires at 272303304595553-272303404595553 nsecs [in 230205077729 to
230305077729 nsecs]
#4: <00000000>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, cupsd/1487
# expires at 273251841003420-273251941003420 nsecs [in 1178741485596 to
1178841485596 nsecs]
clock 1:
.base: 00000000
.index: 1
.resolution: 1 nsecs
.get_time: ktime_get_real
.offset: 1328382209780821967 nsecs
active timers:
clock 2:
.base: 00000000
.index: 2
.resolution: 1 nsecs
.get_time: ktime_get_boottime
.offset: 0 nsecs
active timers:
.expires_next : 272073101562500 nsecs
.hres_active : 1
.nr_events : 3436951
.nr_retries : 201656
.nr_hangs : 0
.max_hang_time : 0 nsecs
.nohz_mode : 2
.idle_tick : 272073070312500 nsecs
.tick_stopped : 0
.idle_jiffies : 34786952
.idle_calls : 6405751
.idle_sleeps : 5671548
.idle_entrytime : 272073086669924 nsecs
.idle_waketime : 272073079986574 nsecs
.idle_exittime : 272073079986574 nsecs
.idle_sleeptime : 234101001227924 nsecs
.iowait_sleeptime: 3747206917044 nsecs
.last_jiffies : 34786954
.next_jiffies : 34786955
.idle_expires : 272074562500000 nsecs
jiffies: 34786956
Tick Device: mode: 1
Broadcast device
Clock Event Device: gp timer
max_delta_ns: 131072454787401
min_delta_ns: 91553
mult: 140737
shift: 32
mode: 3
next_event: 9223372036854775807 nsecs
set_next_event: omap2_gp_timer_set_next_event
set_mode: omap2_gp_timer_set_mode
event_handler: tick_handle_oneshot_broadcast
retries: 166907
tick_broadcast_mask: 00000000
tick_broadcast_oneshot_mask: 00000000
Tick Device: mode: 1
Per CPU device: 0
Clock Event Device: local_timer
max_delta_ns: 12579325019
min_delta_ns: 1000
mult: 358016
shift: 20
mode: 3
next_event: 272073101562500 nsecs
set_next_event: twd_set_next_event
set_mode: twd_set_mode
event_handler: hrtimer_interrupt
retries: 6896962
Tick Device: mode: 1
Per CPU device: 1
Clock Event Device: local_timer
max_delta_ns: 12579325019
min_delta_ns: 1000
mult: 358016
shift: 20
mode: 3
next_event: 272073101562500 nsecs
set_next_event: twd_set_next_event
set_mode: twd_set_mode
event_handler: hrtimer_interrupt
retries: 3890
_______________________________________________
linaro-dev mailing list
linaro-dev@lists.linaro.org
http://lists.linaro.org/mailman/listinfo/linaro-dev
