DAHDI timing and ASL


Steve N4IRS
 
Edited

Along with making ASL more "DVSwitch friendly, We are going to tackle some of the issues that have been bugging (no pun intended) us. First on the list is DAHDI timing. ASL is built with Asterisk 1.4.23 and DAHDI 2.11. I quick Google search will turn up quite a few messages detailing on how important DAHDI timing is to proper Asterisk conference operation. Some of you know that the HAMVIOP fork of the ASL source pushes this a a important difference between ASL and HAMVIOP. I can't really say that I have seen issues in either real hardware or hosted VM based ASL nodes but if timing is important, it's to our advantage to make it the best we can. ASL gets it's timing from DAHDI. DAHDI prefers a hardware source for the clock but if none is available, DAHDI can generate the clock from the host itself. For DAHDI to use the High Resolution Timer in the host, a second DAHDI kernel module is needed. That module is dahdi_dummy. The version of DAHDI shipped with ASL does not include building and installing dahdi_dummy. Since I was the one that packaged DAHDI, all I can say is oops. Below is a timing test I ran on a HP DL360 G5. This is a actual server running Stretch but you will see improvement on a VM or a SBC like the Pi. First we will run without dahdi_dummy.

root@demo:/home/szingman# lsmod | grep dahdi
dahdi                 229376  0
crc_ccitt              16384  1 dahdi

root@demo:/home/szingman# dahdi_test -c 100
Opened pseudo dahdi interface, measuring accuracy...
99.608% 99.996% 99.999% 99.218% 99.997% 99.999% 99.999% 99.999%
99.606% 99.998% 99.999% 99.999% 99.610% 99.999% 99.999% 99.999%
99.999% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 99.999% 99.999% 99.220% 99.220% 99.218% 99.222% 99.999%
99.999% 99.998% 99.999% 99.999% 99.999% 99.999% 99.999% 99.218%
99.222% 99.219% 99.999% 99.222% 99.999% 99.997% 99.999% 99.999%
99.999% 99.999% 99.999% 99.220% 99.222% 99.999% 99.999% 99.999%
99.999% 99.996% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 99.998% 99.999% 99.999% 99.220% 99.220% 99.997% 99.999%
99.999% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.220% 99.223% 99.220% 99.222% 99.999% 99.999% 99.997% 99.999%
99.999% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 100.000%
--- Results after 98 passes ---
Best: 100.000% -- Worst: 99.218% -- Average: 99.851760%
Cumulative Accuracy (not per pass): 99.997

root@demo:/usr/src/asl-dahdi-linux-2.11.1# dahdi_scan
NO OUTPUT at all

Now we will run after adding dahdi_dummy

root@demo:/home/szingman# lsmod | grep dahdi
dahdi_dummy            16384  0
dahdi                 229376  1 dahdi_dummy
crc_ccitt              16384  1 dahdi

root@demo:/home/szingman# dahdi_test -c 100
Opened pseudo dahdi interface, measuring accuracy...
99.998% 99.996% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 99.998% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 99.998% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 99.998% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 99.998% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 99.998% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 99.998% 99.999% 99.999% 99.999% 99.999% 99.994% 99.999%
99.999% 99.998% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 99.998% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 99.998% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 99.998% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 99.998% 99.999% 99.999% 99.999% 99.999% 99.999% 99.999%
99.999% 99.998%
--- Results after 98 passes ---
Best: 99.999% -- Worst: 99.994% -- Average: 99.998769%
Cumulative Accuracy (not per pass): 99.999

root@demo:/home/szingman# dahdi_scan
[1]
active=yes
alarms=UNCONFIGURED
description=DAHDI_DUMMY/1 (source: HRtimer) 1
name=DAHDI_DUMMY/1
manufacturer=
devicetype=DAHDI Dummy Timing
location=
basechan=1
totchans=0
irq=0

As you can see there is a improvement. Not a big improvement in this case but there is a difference. We have tested on a few different platforms and all exhibit a improvement. It's actually easy to build and install the dahdi_dummy module.

As root:
edit /usr/src/asl-dahdi-linux-2.11.1/linux/drivers/dahdi/Kbuild
change:
#obj-$(DAHDI_BUILD_ALL)$(CONFIG_DAHDI_DUMMY)             += dahdi_dummy.o     
to:
obj-$(DAHDI_BUILD_ALL)$(CONFIG_DAHDI_DUMMY)             += dahdi_dummy.o
save your work.

cd to /usr/src/asl-dahdi-linux-2.11.1
run:
make install
Once make completes, test your work:
modprobe dahdi_dummy
You should see:
root@demo:/home/szingman# lsmod | grep dahdi
dahdi_dummy            16384  0
dahdi                 229376  1 dahdi_dummy
crc_ccitt              16384  1 dahdi

If you do, the module is built and can be installed.
Now we will load it at boot.
edit /etc/modules
add dahdi_dummy above dahdi
save your work
reboot

This was discovered by Bryan W9CR. He compared the binary for dahdi_dummy with what HAMVOIP calls dahdi_hrtimer. A comparison using strings turns up some glaring similarities and differences. I'll leave this to the community to decide.
Here are some other tests and results. Note: some eagle eyed users will notice some of these tests were not run on the HP DL360 G5. I do not have ASL installed on that machine yet, only DAHDI:

Before:
root@repeater:/home/szingman# lsmod | grep dahdi
dahdi                 229376  0
crc_ccitt              16384  1 dahdi

root@repeater:/home/repeater# asterisk -r

AllStarLink Asterisk Version 1.01 2/13/2018 GIT Version adaec47
=========================================================================
Connected to Asterisk GIT Version adaec47 currently running on repeater (pid = 353)
repeater*CLI> dahdi show status
Description                              Alarms     IRQ        bpviol     CRC4
repeater*CLI> exit

After:
root@repeater:/home/repeater# modprobe dahdi_dummy
root@repeater:/home/repeater# lsmod | grep dahdi
dahdi_dummy             3538  0
dahdi                 233213  27 dahdi_dummy
crc_ccitt               1835  1 dahdi


root@repeater:/home/repeater# asterisk -r

AllStarLink Asterisk Version 1.01 2/13/2018 GIT Version adaec47
=========================================================================
Connected to Asterisk GIT Version adaec47 currently running on repeater (pid = 353)
repeater*CLI> dahdi show status
Description                              Alarms     IRQ        bpviol     CRC4
DAHDI_DUMMY/1 (source: HRtimer) 1        UNCONFIGUR 0          0          0
repeater*CLI>

<

https://elinux.org/High_Resolution_Timers#How_to_detect_if_your_timer_system_supports_high_resolution>

Here are some things to check:

1. Check the resolution reported for your clocks. If your clock supports high resolution, it will have a .resolution value of 1 nsecs. If it does not, then it will have a .resolution value that equals the number of nanoseconds in a jiffy (usually 10000 nsecs, on embedded platforms).

2. Check the event_handler for the Tick Device. If the event handlers is 'hrtimer_interrupt' then the clock is set up for high resolution handling. If the event handler is 'tick_handle_periodic', then the device is set up for regular tick-based handling.

3. Check the list of timers, and see if the attribute .hres_active has a value of 1. If so, then the high resolution timer feature is active.


root@repeater:/home/repeater# cat /proc/timer_list
Timer List Version: v0.8
HRTIMER_MAX_CLOCK_BASES: 4
now at 927502067184 nsecs

cpu: 0
 clock 0:
  .base:       df91dd80
  .index:      0
  .resolution: 1 nsecs
  .get_time:   ktime_get
  .offset:     0 nsecs
active timers:
 #0: zaptimer, dahdi_dummy_hr_int, S:01, init_module, systemd-modules/189
 # expires at 927506314625-927506314625 nsecs [in 4247441 to 4247441 nsecs]
 #1: <df91e020>, tick_sched_timer, S:01, tick_nohz_restart, swapper/0/0
 # expires at 927508000000-927508000000 nsecs [in 5932816 to 5932816 nsecs]
 #2: <dacffa30>, hrtimer_wakeup, S:01, schedule_hrtimeout_range_clock, asterisk/458
 # expires at 927520910752-927520960752 nsecs [in 18843568 to 18893568 nsecs]
 #3: <dabeda30>, hrtimer_wakeup, S:01, schedule_hrtimeout_range_clock, asterisk/419
 # expires at 927728645724-927729645716 nsecs [in 226578540 to 227578532 nsecs]
 #4: <dc665a30>, hrtimer_wakeup, S:01, schedule_hrtimeout_range_clock, asterisk/372
 # expires at 927948646756-927953646748 nsecs [in 446579572 to 451579564 nsecs]
 #5: <df91e138>, watchdog_timer_fn, S:01, watchdog_enable, watchdog/0/11
 # expires at 928092000000-928092000000 nsecs [in 589932816 to 589932816 nsecs]
 #6: <dad8fee8>, hrtimer_wakeup, S:01, do_nanosleep.constprop.5, asterisk/418
 # expires at 928413787609-928413837609 nsecs [in 911720425 to 911770425 nsecs]
 #7: <dc3b6800>, timerfd_tmrproc, S:01, SyS_timerfd_settime, systemd-udevd/230
 # expires at 940154557000-940154557000 nsecs [in 12652489816 to 12652489816 nsecs]
 #8: <dc3b6a00>, timerfd_tmrproc, S:01, SyS_timerfd_settime, systemd-journal/184
 # expires at 940154557000-940154557000 nsecs [in 12652489816 to 12652489816 nsecs]
 #9: <dc3b6000>, timerfd_tmrproc, S:01, SyS_timerfd_settime, systemd/1
 # expires at 940154557000-940154557000 nsecs [in 12652489816 to 12652489816 nsecs]
 #10: <dc6cdee8>, hrtimer_wakeup, S:01, do_nanosleep.constprop.5, cron/381
 # expires at 949573630626-949573680626 nsecs [in 22071563442 to 22071613442 nsecs]
 #11: <dc413ee8>, hrtimer_wakeup, S:01, do_nanosleep.constprop.5, sleep/654
 # expires at 953799741074-953799791074 nsecs [in 26297673890 to 26297723890 nsecs]
 #12: sched_clock_timer, sched_clock_poll, S:01, sched_clock_postinit, swapper/0/0
 # expires at 984263334681-984263334681 nsecs [in 56761267497 to 56761267497 nsecs]
 #13: <daadd500>, timerfd_tmrproc, S:01, SyS_timerfd_settime, systemd-logind/377
 # expires at 1000154557000-1000154557000 nsecs [in 72652489816 to 72652489816 nsecs]
 #14: <daacf600>, timerfd_tmrproc, S:01, SyS_timerfd_settime, systemd-timesyn/334
 # expires at 1000154557000-1000154557000 nsecs [in 72652489816 to 72652489816 nsecs]
 #15: <db1b5a30>, hrtimer_wakeup, S:01, schedule_hrtimeout_range_clock, rsyslogd/353
 # expires at 1211996410283-1212096410283 nsecs [in 284494343099 to 284594343099 nsecs]
 #16: <dace3ee8>, hrtimer_wakeup, S:01, do_nanosleep.constprop.5, asterisk/371
 # expires at 1217714212774-1217714262774 nsecs [in 290212145590 to 290212195590 nsecs]
 #17: <dc6a1a30>, hrtimer_wakeup, S:01, schedule_hrtimeout_range_clock, dhclient/474
 # expires at 36579226391252-36579326391252 nsecs [in 35651724324068 to 35651824324068 nsecs]
 clock 1:
  .base:       df91ddc0
  .index:      1
  .resolution: 1 nsecs
  .get_time:   ktime_get_real
  .offset:     1570714932000715417 nsecs
active timers:
 #0: <daadd200>, timerfd_tmrproc, S:01, SyS_timerfd_settime, systemd/1
 # expires at 1570716580154557000-1570716580154557000 nsecs [in 720651774399 to 720651774399 nsecs]
 #1: <da930800>, timerfd_tmrproc, S:01, SyS_timerfd_settime, systemd/1
 # expires at 2147483647000000000-2147483647000000000 nsecs [in 576767787497217399 to 576767787497217399 nsecs]
 #2: <daadde00>, timerfd_tmrproc, S:01, SyS_timerfd_settime, systemd-timesyn/334
 # expires at 2147483647000000000-2147483647000000000 nsecs [in 576767787497217399 to 576767787497217399 nsecs]
 #3: <dc645b00>, timerfd_tmrproc, S:01, SyS_timerfd_settime, systemd/570
 # expires at 2147483647000000000-2147483647000000000 nsecs [in 576767787497217399 to 576767787497217399 nsecs]
 clock 2:
  .base:       df91de00
  .index:      2
  .resolution: 1 nsecs
  .get_time:   ktime_get_boottime
  .offset:     0 nsecs
active timers:
 #0: <dc6db500>, timerfd_tmrproc, S:01, SyS_timerfd_settime, systemd-timesyn/334
 # expires at 1045654557000-1045654557000 nsecs [in 118152489816 to 118152489816 nsecs]
 clock 3:
  .base:       df91de40
  .index:      3
  .resolution: 1 nsecs
  .get_time:   ktime_get_clocktai
  .offset:     1570714932000715417 nsecs
active timers:
  .expires_next   : 927506314625 nsecs
  .hres_active    : 1
  .nr_events      : 942016
  .nr_retries     : 42
  .nr_hangs       : 0
  .max_hang_time  : 0
  .nohz_mode      : 2
  .last_tick      : 927488000000 nsecs
  .tick_stopped   : 0
  .idle_jiffies   : 156871
  .idle_calls     : 912199
  .idle_sleeps    : 879117
  .idle_entrytime : 927492366427 nsecs
  .idle_waketime  : 927492366427 nsecs
  .idle_exittime  : 927492554513 nsecs
  .idle_sleeptime : 697520844910 nsecs
  .iowait_sleeptime: 6054951872 nsecs
  .last_jiffies   : 156872
  .next_timer     : 927520000000
  .idle_expires   : 927520000000 nsecs
jiffies: 156876

Tick Device: mode:     1
Broadcast device
Clock Event Device: <NULL>
tick_broadcast_mask: 0
tick_broadcast_oneshot_mask: 0

Tick Device: mode:     1
Per CPU device: 0
Clock Event Device: timer2
 max_delta_ns:   178956969070
 min_delta_ns:   1000
 mult:           51539608
 shift:          31
 mode:           3
 next_event:     927506314625 nsecs
 set_next_event: omap2_gp_timer_set_next_event
 shutdown: omap2_gp_timer_shutdown
 periodic: omap2_gp_timer_set_periodic
 oneshot:  omap2_gp_timer_shutdown
 resume:   omap2_gp_timer_shutdown
 event_handler:  hrtimer_interrupt
 retries:        104

73, Steve N4IRS

Join DVSwitch-AllStar@DVSwitch.groups.io to automatically receive all group messages.