# : >/var/log/kern.log; cat /proc/interrupts; /bin/time insmod houba.ko; cat /proc/interrupts; rmmod houba
CPU0
0: 519083 XT-PIC-XT timer
2: 0 XT-PIC-XT cascade
9: 0 XT-PIC-XT acpi
10: 9786 XT-PIC-XT eth0
11: 5 XT-PIC-XT eth1
12: 5 XT-PIC-XT eth2
14: 16920 XT-PIC-XT ide0
NMI: 0
ERR: 0
0.00user 0.00system 5:00.00elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+111minor)pagefaults 0swaps
CPU0
0: 549094 XT-PIC-XT timer
2: 0 XT-PIC-XT cascade
9: 0 XT-PIC-XT acpi
10: 9791 XT-PIC-XT eth0
11: 5 XT-PIC-XT eth1
12: 5 XT-PIC-XT eth2
14: 16970 XT-PIC-XT ide0
NMI: 0
ERR: 0
(HZ=100)
30011 timer interrupts
5 eth0 interrupts
50 ide0 interrupts
# cat /var/log/kern.log
Apr 17 18:22:27 SEND kernel: INIT
Apr 17 18:27:27 SEND kernel: 2350080 29995
Apr 17 18:27:27 SEND kernel: 2369792 1
Apr 17 18:27:27 SEND kernel: 2440192 1
Apr 17 18:27:27 SEND kernel: 2441216 1
Apr 17 18:27:27 SEND kernel: 2583296 1
Apr 17 18:27:27 SEND kernel: 2852096 1
Apr 17 18:27:27 SEND kernel: EXIT
First column is the cycle count clamped to a multiple of 256.
(1266.7 MHz CPU)
Second column is occurence count.
In the second experiment, I added the IRQ disable/enable around foo.
# : >/var/log/kern.log; cat /proc/interrupts; /bin/time insmod houba.ko; cat /proc/interrupts; rmmod houba
CPU0
0: 583666 XT-PIC-XT timer
2: 0 XT-PIC-XT cascade
9: 0 XT-PIC-XT acpi
10: 10084 XT-PIC-XT eth0
11: 5 XT-PIC-XT eth1
12: 5 XT-PIC-XT eth2
14: 17012 XT-PIC-XT ide0
NMI: 0
ERR: 0
0.00user 0.01system 5:00.00elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+110minor)pagefaults 0swaps
CPU0
0: 613677 XT-PIC-XT timer
2: 0 XT-PIC-XT cascade
9: 0 XT-PIC-XT acpi
10: 10089 XT-PIC-XT eth0
11: 5 XT-PIC-XT eth1
12: 5 XT-PIC-XT eth2
14: 17070 XT-PIC-XT ide0
NMI: 0
ERR: 0
30011 timer interrupts
5 eth0 interrupts
58 ide0 interrupts
# cat /var/log/kern.log
Apr 17 18:33:12 SEND kernel: INIT
Apr 17 18:38:12 SEND kernel: 2350080 30000
Apr 17 18:38:12 SEND kernel: EXIT
In this experiment, all the calls to foo had a latency between
2350080 and 2350335 cycles (1.88528 to 1.88548 ms).
I don't think I can conclude anything based on this experiment.
I'll let it run all night long.