Friday, 25 February 2011

Importance of the scheduling priority in D-Bus

Context switches are expensive. When do they happen in D-Bus communication?

application1 sends a D-Bus message to application2 through dbus-daemon

The kernel may perform a context switch:

During the sendmsg() system call, when application1 sends a D-Bus message to dbus-daemon

During the sendmsg() system call, when dbus-daemon sends a D-Bus message to application2

At the end of a time slice

I instrumented libdbus in order to trace events such as message parsing, dispatching messages in dbus-daemon, sendmsg(), recvmsg(). I took inspiration from Federico’s performance scripts but without using strace because straced processes have a big overhead compared to the duration of events I want to measure. My instrumentation doesn’t save traced events in a file to avoid overhead as much as possible, but just keep them in memory and save them after the experiment is finished. This is triggered:

when a process using libdbus exits. The save function is registered by atexit().

when a process using libdbus receives a SIGUSR2 signal. The save function is registered by sigaction().

I collect logs generated by dbus-daemon and all D-Bus peers and feed them to plot-timeline.py to generate timelines. I estimate the overhead of logging between 3 microseconds and 5 microseconds by logging consecutively 2 events. All the experiments are run in a virtual machine with one processor.

Experiment #1: a D-Bus signal delivered to 10 recipients

I sent one D-Bus signal with dbus-send and received by 10 dbus-monitor. You can reuse this script.

In this experiment, dbus-send was context switched off during the send() system call and that system call returned after dbus-daemon received the message, sent it to the 10 recipients, and all of them received it.

We can see dbus-daemon iterating over every recipients and sending the message on each recipient’s socket.

There is 12 context switches in this experiment:

1 context switch from the sender to dbus-daemon

10 context switches to each recipient

1 final context switch to the sender

Experiment #2: 10 D-Bus signal delivered to 10 recipients

It is the same experiment as before but the sender emits 10 D-Bus signals (as fast as it could) instead of a single one. dbus-send cannot do that, so I used dbus-ping-pong.

The first three D-Bus signal are delivered in the same way; this timeline looks like the first timeline. There is also 12 context switches per D-Bus signal emitted.

But something different happen for the 7 next D-Bus signals: dbus-daemon is context switched off during the send() on every recipient.

The scheduler tries to maintain fairness along all the processes by giving them the same amount of CPU time. But dbus-daemon has about 10 times more work to do than every single recipient because it sends 10 messages and the recipients only receive 1 message. So when dbus-daemon writes on a recipient’s socket, there is two processes in the running state and the scheduler has to take a decision between a CPU hungry process (dbus-daemon) and a recipient. The recipient is chosen and it causes a context switches.

The context switches per D-Bus signal emitted are:

1 context switch from the sender to dbus-daemon

1 context switch from dbus-daemon to the first recipient

1 context switch from the first recipient back to dbus-daemon

again 2 times 9 context switches between dbus-daemon and the remaining recipients

1 context switch from dbus-daemon to the sender

That’s 22 context switches in total instead of 12 for the same amount of work and the same amount of messages delivered.