Out of the loop for a while...

I'm heading into hospital for an operation on my neck later today and recuperation may take a while. Hence this blog is not going to be updated for quite a few weeks.

Meanwhile, while I'm away, please feel free to add comments on the kind of kernel/system/BIOS related issues you're interested in to help me focus blog entries in 2010...

UPDATE:

Operation was a success - now got a titanium disc in my neck and I've regained sense of touch in feet and hands. I can now walk again without the help of a walking stick. I'm keeping my keyboarding/desk activity to absolute minimum. Need to do a whole load of exercises to get neck more mobile and my immune system is working overtime which makes me really physically tired.

itop - look at top interrupt activity

When I want to see interrupt activity on a Linux box I normally use the following rune:

watch -n 1 cat /proc/interrupts

..which simply dumps out the interrupt information every second.  Another way is to use itop, which has the benefit that it outputs the interrupt rate which is lacking from my rune above.

To install, use:

sudo apt-get install itop

and to run, use:

itop

The output is refreshed every second, and outputs something like the following:

INT                NAME          RATE             MAX
  0 [PIC-edge      time]   154 Ints/s     (max:   154)
 14 [PIC-edge      ata_]    16 Ints/s     (max:    16)
 18 [PIC-fasteoi   ehci]     4 Ints/s     (max:     4)
 22 [PIC-fasteoi   ohci]     2 Ints/s     (max:     2)
 29 [MSI-edge      i915]    38 Ints/s     (max:    38)
 30 [MSI-edge      iwl3]     6 Ints/s     (max:     6)

Unfortunately itop does truncate the interrupt names, but I'm not so worried about this - I generally want to see very quickly if a machine is suffering from interrupt saturation or is missing interrupts, which I can get from itop easily.

To see all interrupts, run itop with:

itop -a

And to run for a number of iterations, run with the -n flag, e.g.

itop -n 10

Kernel Early Printk Messages

I've been messing around with the earlyprintk kernel options to allow me to get some form of debug out before the console drivers start later on in the kernel init phase. The earlyprintk kernel option supports debug output via the VGA, serial port and USB debug port.

The USB debug port is of interest - most modern systems seem to provide a debug port capability which allows one to send debug over USB to another machine. To check if your USB controller has this capability, use:

sudo lspci -vvv | grep "Debug port"

and look for a string such as "Capabilities: [58] Debug port: BAR=1 offset=00a0". You may have more than one of these on your system, so beware you use the correct one.

One selects this mode of earlyprintk debugging using:

earlyprintk=dbgp

for the default first port, or select the Nth debug enabled port using:

earlyprintk=dbgpN

One also needs to build a kernel with the following config option enabled:

CONFIG_EARLY_PRINTK_DBGP=y

On my debug set-up I used a NET20DC-USB Hi-Speed USB 2.0 Host-to-Host Debug Device connecting the target machine and a host with which I capture the USB debug using /dev/ttyUSB0 with minicom. So that I won't bore you with the details, this is all explained in the kernel documentation in Documentation/x86/earlyprintk.txt

As it was, I needed to tweak the earlyprintk driver to put in some delays in the EHCI probing and reset code to get it working on my fairly fast target laptop.
My experience with this approach wasn't great - I had to plug/unplug the debug device quite frequently for the earlyprintk EHCI reset and probe to work. Also, the EHCI USB driver initialisation later on in the kernel initialisation hung which wasn't useful.

Overall, I may have had problems with the host/target and/or the NET20DC-USB host-to-host device, but it did allow me to get some debug out, be it rather unreliably.

Probably an easier way to get debug out is just using the boot option:

earlyprintk=vga

however this has the problem that the messages are eventually overwritten by the real console.

Finally, for anyone with old legacy serial ports on their machine (which is quite unlikely nowadays with newer hardware), one can use:

earlyprintk=serial,ttySn,baudrate

where ttySn is the nth tty serial port.

One can also append the ",keep" option to not disable the earlyprintk once the real console is up and running.

So, with earlyprintk, there is some chance of being able to get some form of debug out to a device to allow one to debug kernel problems that occur early in the initialisation phase.

Results from the "Linux needs to have..." poll

Before I kick off another poll, here are the totally unscientific results of my "Linux needs to have..." poll:

Working Audio	16
Reliable suspend/resume	11
Better video support	10
Better battery life	9
Better wifi	8
Faster boot times	6
Nothing more - it rocks	2

It's based on a very small sample (even though we get thousands of hits a month), so I'd hate to draw many conclusions from the votes. However, it looks like audio is giving a lot of users grief and this needs fixing.  Making Suspend/Resume better does not surprise me as I see a lot of weird ACPI and driver suspend/resume issues on the hardware I work with.   It's interesting to see that faster boot times are low on the wish list,  but I does not surprise me that video and wifi support are higher priority (since they need to work!) compared to getting to boot faster.

And to finish with, not many users think Linux does not need improving - this spurs us on to get subsystems fixed to make it rock!

Debugging grub2 with gdb

Ľubomír Rintel has written a detailed and very helpful debugging guide for grub2. The guide covers how to debug with gdb using emulators such as QEMU and Bochs as well as traditional serial line debugging using a null-modem.

The tricky part is to be able to pull in the debug and symbol files for dynamically loaded modules, however this has been solved by Ľubomír with a gdb and perl script.

The guide gives some useful tricks which can be used not just with grub2 but other boot loaders too. It's well worth a look just to learn some useful gdb hacks.

Chumby One - Cute and affordable fun.

A little while ago I blogged about the Chumby, a fine little ARM+Linux based internet device made by Chumby Industries.

Well, now they have gone one step futher and produced the Chumby One (see right), which currently retails for $99 for pre-orders. This new version comes with some extra features compared to the original: an FM radio, support for a rechargeable lithium ion battery an easier to use volume dial.

There is a great blog article about design rationale behind this new product on Bunnies Blog including a video of the production line and some photos of the motherboard.

I'm quite a fan of the Chumby Classic, but it's great to see a far more affordable little brother being added to the product range! I wish Chumby Industries every success with the Chumby One.

Debugging with QEMU and gdb

QEMU is one very powerful tool - and combined with gdb this has allowed me to debug Intel based boot loaders. Here is a quick run down of the way I drive this:

Firstly, I recommend removing KVM as this has caused me some grief catching breakpoints. This means QEMU will run slower, but I want to remove any kind of grief I can to simplify my debugging environment.

Start QEMU and use the -s -S options to enable gdb debugging and halt the CPU to wait for gdb to attach:

$ qemu -s -S -bios bios-efi.bin -m 1024 karmic-efi-qcow2.img -serial stdio

..then in another terminal, attach gdb:

$ gdb
GNU gdb (GDB) 7.0-ubuntu
Copyright (C) 2009 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.

(gdb) target remote localhost:1234
Remote debugging using localhost:1234
0x0000fff0 in ?? ()
(gdb)

..and start the boot process..

(gdb) c

..and get debugging!

Bash file truncation

Today I wanted to truncate a file from bash and discovered that using the dummy placeholder : worked a treat:

:>example-file-to-truncate.txt

..I've been using bash for years and completely overlooked this gem - I should have devoted more effort into reading the POSIX 1003.2 standard or the bash manual a long while ago...

Booting Ubuntu Karmic with grub2 and EFI

The past few days I've been tinkering with the TianoCore EFI and trying to get Ubuntu Karmic to boot with the EFI enabled grub2. To make debugging easier, I did all this inside a virtualised QEMU environment. A lot of this earlier hackery was blogged about in a previous article.

In trying to get this to work I hit a couple of issues; figuring out workarounds took some thought and time. Some of it is still "work in progress", but at least now I know what needs to be fixed.

Below is a video (grabbed using the recordmydesktop tool) showing Ubuntu Karmic booting:






First you see the TianoCore EFI starting and then loading grub2 - this then loads a very slimmed down grub.cfg and eventually boots the system.

I hit several issues; firstly the kernel oops'd when trying to call virt_efi_get_next_variable() - for some reason calling this EFI runtime service support function in the EFI is causing the kernel to oops. Other EFI support functions seem to work correctly, so my current belief is that the bug is not in the kernel EFI driver, but this needs a little more poking around to verify this assumption.

Second issue is that loading some grub2 modules and using some fundamental grub2 commands such as 'set' cause the EFI get caught in a loop. It took me a while to corner this - eventually I cut down the default grub config file down to a really minimal version which could at least boot the kernel! Anyhow, this grub2 issue is first on my list of bugs to fix.

Debugging these issues is a little tricky, but using QEMU helps as I can dump out debug from grub2 over a pseudo serial port which I can capture and view in real-time. Secondly, debugging the kernel using a serial console in QEMU (using the console=ttyS0 boot option) allows me to capture all kernel boot messages (including the offending kernel oops).

I still need to look into ACPI support and how to get the video initialised to get more than bog-standard VGA resolution, but these are currently lower priorities.

Without QEMU and Tristan Gingold's port of the TianoCore EFI to QEMU, this work would have been much harder.

Improving battery life on the HP Mini

A few weeks ago I wrote about my experience using an HP Mini netbook - well in this follow up article describes how I reduced the power consumption on this device with some fairly basic steps.

I started from a fresh clean install of Ubuntu Karmic 9.10 (32 bit) and pulled in all the latest updates. I then installed powertop using:

apt-get install powertop

Then I unplugged the power and let powertop run for 10 minutes to settle in and then noted that ACPI power estimate was ~13.0W.

My first saving was to totally disable Bluetooth - wireless power savings are a good way of saving power. I don't use Bluetooth at all and to save memory from the driver being loaded I blacklisted the btusb module by adding btusb to /etc/modprobe.d/blacklist.conf (this is rather a heavy handed approach!). I then rebooted and re-measured the power consumption - down to 9.7W.

My next tweak was to enable laptop mode. To do this, edit /etc/default/acpi-support and set ENABLE_LAPTOP_MODE=true. Not sure if this is a big win for devices with SSD like my netbook, I believe one will see a bigger power saving with HDD based devices using this setting.

I noted that powertop was informing me to use usbcore.autosuspend=1 and disable hal polling, so I'd thought I'd follow it's wisdom and make these tweaks.

I edited /etc/default/grub and changed the GRUB_CMDLINE_LINUX_DEFAULT setting by adding usbcore.autosuspend=1, and then ran sudo update-grub to update /boot/grub/grub.cfg.

Next I ran:

sudo hal-disable-polling --device /dev/sdb

..for some reason /dev/sdb was being polled and I don't require this overhead for some auto sensing functionality.

I rebooted and remeasured the power consumption - down to 8.7W. Not bad.

Next I totally disabled compiz and turned my display brightness down - this saved 0.3W, bringing the the system down to a reasonable 8.4W. I'm not sure if the compiz savings were much, but if I can save the GPU work by turning off compositing then that must save some power.

My final tweak was to disable the Gnome terminal cursor from flashing - this saves 2 wakeups a second (not much!). To disable the cursor blink for the Default profile I ran gconf-editor and set /apps/gnome-terminal/profiles/Default/cursor_blink_mode to off. This saving is negligible, but makes me feel good to know I've saved two wakeups a second :-)

So now my machine was in a usable state, and down to 8.4W. I could tweak my access point to reduce the number of beacon intervals to save Wifi wakeups, but that's going a little too far, even for me! I then wondered much power Wifi was using, so I disabled it and after 15 minutes my system dropped down to 7.3W. This is good to know but a little pointless for my normal work pattern when I need net access - it is a netbook after all!

I'm sure I can save a little more power, but for now it's a good win for a little amount of work. I'm open to any suggestions on how to save more power. Please let me know!

Audio Weirdnesses

Yesterday I got poking around a perplexing audio recording issue; quite bizarrely stereo (2 channel) audio from the internal microphone would record perfectly, but mono (1 channel) would not. After working my way down through the driver and though ALSA I got to the point where I could not see how there could be any driver problem, so the issue had to be with the ALSA user space library, or the hardware (or both!).

My colleague spotted an interesting characteristic - using alsamixer to set the capture level to 100% left channel and 0% right channel or vice-versa made the mono recording work. Further investigation by using stereo recording of a pure sine wave (whistling into the microphone!) showed that the left channel was the complete reverse of the right channel. Then the penny dropped - the mono recording was essentially ALSA summing left and right channels, causing a near perfect zero recording since the left channel was the inverse of the right channel. Doh.

As it is, this very same issue has been discussed on LKML here with a suggested workaround described by Takashi Iwai here as follows:

Put the below to ~/.asoundrc

pcm.imix {
 type plug
 slave.pcm "hw"
 ttable.0.0 0.5
 ttable.0.1 -0.5
}

And record using:

arecord -Dimix -c1 test.wav

Urgh. Well, at least there is some kind of ALSA workaround.

So the moral of the story is to twiddle with left and right channel levels and do some stereo recording and look at the results before hacking through the driver. I should have applied Occams' razor - I assumed the complex part (the driver) was the problem.

QEMU and EFI BIOS hackery

Earlier this week I blogged about QEMU and EFI BIOS. Trying to debug a problem with grub2-efi-ia32 has given me a few little headaches but I'm finding ways to work around them all.

The first issue is getting a system installed with an EFI BIOS. My quick hack was to create a 4GB QEMU qcow2 disk image and then inside this create a small EFI FAT12 boot partition using fdisk - (partition type 0xef in the 1st primary partition). I then installed Ubuntu Karmic Desktop with ext4 and swap in primary partitions 2 and 3 by booting with the conventional BIOS. I then installed grub2-efi-ia32 in the EFI boot partition and then booted QEMU using the TianoCore EFI BIOS that has been ported to QEMU.

One problem is that the EFI BIOS does not scroll the screen, hence all output when it reaches the end of the screen just keeps over writing the last line, making debugging with printf() style prints nearly impossible. Then I found that the BIOS emits characters over a serial port, which QEMU can emulate. Unfortunately, the output contains VT control characters to do cursor positioning and pretty console colours, which makes reading the output a little painful. So I hacked up a simple tool to take the output from QEMU and strip out the VT control chars to make the text easier to read.

Now QEMU boot line is as follows:

qemu -bios bios-efi.bin -m 1024 karmic-efi-qcow2.img -serial stdio 2>&1 | ./parse-output

..and this dumps the output from the BIOS and grub2 to stdout in a more readable form.

The parse-output tool is a little hacky - but does the job. For reference, I've put it in my debug repository here.

Grub2 allows one to enable some level of debugging output by issuing the following command:

set debug=all

..which gives me some idea of what's working or broken at a fairly low enough level before I start attaching gdb. Fortunately debugging using gdb has been fairly well documented here - I just now need to shoe-horn in small patch to allow me to attach gdb to grub2 from outside QEMU - but that's for another debug session...

Performance Monitoring using Ingo Molnars' perf tool

The perf tool by Ingo Molnar allows one to do some deep performance using Linux performance counters. It covers a broad range of performance monitoring at the hardware level and software level. In this blog posting I just want to give you a taste of some of the ways to use this powerful tool.

One needs to build this from the kernel source, but it's fairly easy to do:

1) Install libelf-dev, on a Ubuntu system use:

sudo apt-get install libelf-dev

2) Get the kernel source

either from kernel.org or from Ubuntu kernel source package:

apt-get source linux-image-2.6.31-14-generic

3) ..and build the tool..

in the kernel source:

cd tools/perf
make

There is plenty of documentation on this tool in the tools/perf/Documentation directory and I recommend reading this to get a full appreciation of what the tool can do and how to drive it.

My first example is a trivial performance counter example on the dd command:

./perf stat dd if=/dev/zero of=/dev/null bs=1M count=4096
4096+0 records in
4096+0 records out
4294967296 bytes (4.3 GB) copied, 0.353498 s, 12.1 GB/s

Performance counter stats for 'dd if=/dev/zero of=/dev/null bs=1M count=4096':

355.148424 task-clock-msecs # 0.998 CPUs
18 context-switches # 0.000 M/sec
0 CPU-migrations # 0.000 M/sec
501 page-faults # 0.001 M/sec
899141721 cycles # 2531.735 M/sec
2212730050 instructions # 2.461 IPC
67433134 cache-references # 189.873 M/sec
6374 cache-misses # 0.018 M/sec

0.355829317 seconds time elapsed

But we can dig deeper than this. How about seeing what's really going on on the application and the kernel? The next command records stats into a file perf.data and then we can then examine these stats using perf report:

./perf record -f dd if=/dev/urandom of=/dev/null bs=1M count=16
16+0 records in
16+0 records out
16777216 bytes (17 MB) copied, 2.39751 s, 7.0 MB/s
[ perf record: Captured and wrote 1.417 MB perf.data (~61900 samples) ]

..and generate a report on the significant CPU consuming functions:

./perf report --sort comm,dso,symbol | grep -v "0.00%"
# Samples: 61859
#
# Overhead Command Shared Object Symbol
# ........ ....... ......................... ......
#
75.52% dd [kernel] [k] sha_transform
14.07% dd [kernel] [k] mix_pool_bytes_extract
3.38% dd [kernel] [k] extract_buf
2.33% dd [kernel] [k] copy_user_generic_string
1.36% dd [kernel] [k] __ticket_spin_lock
0.90% dd [kernel] [k] _spin_lock_irqsave
0.72% dd [kernel] [k] _spin_unlock_irqrestore
0.67% dd [kernel] [k] extract_entropy_user
0.27% dd [kernel] [k] default_spin_lock_flags
0.22% dd [kernel] [k] sha_init
0.11% dd [kernel] [k] __ticket_spin_unlock
0.08% dd [kernel] [k] copy_to_user
0.04% perf [kernel] [k] copy_user_generic_string
0.02% dd [kernel] [k] clear_page_c
0.01% perf [kernel] [k] memset_c
0.01% dd [kernel] [k] page_fault
0.01% dd /lib/libc-2.10.1.so [.] 0x000000000773f6
0.01% perf [kernel] [k] __ticket_spin_lock
0.01% dd [kernel] [k] native_read_tsc
0.01% dd /lib/libc-2.10.1.so [.] strcmp
0.01% perf [kernel] [k] kmem_cache_alloc
0.01% perf [kernel] [k] __block_commit_write
0.01% perf [kernel] [k] ext4_do_update_inode

..showing us where most of the CPU time is being consumed, down to the function names in the kernel, application and shared libraries.

One can drill down deeper, in the previous example strcmp() was using 0.01% of the CPU; we can see where using perf annotate:

./perf annotate strcmp
objdump: 'vmlinux': No such file

------------------------------------------------
Percent | Source code & Disassembly of vmlinux
------------------------------------------------
------------------------------------------------
Percent | Source code & Disassembly of libc-2.10.1.so
------------------------------------------------
:
:
:
: Disassembly of section .text:
:
: 000000000007ee20 :
50.00 : 7ee20: 8a 07 mov (%rdi),%al
0.00 : 7ee22: 3a 06 cmp (%rsi),%al
25.00 : 7ee24: 75 0d jne 7ee33
25.00 : 7ee26: 48 ff c7 inc %rdi
0.00 : 7ee29: 48 ff c6 inc %rsi
0.00 : 7ee2c: 84 c0 test %al,%al
0.00 : 7ee2e: 75 f0 jne 7ee20
0.00 : 7ee30: 31 c0 xor %eax,%eax
0.00 : 7ee32: c3 retq
0.00 : 7ee33: b8 01 00 00 00 mov $0x1,%eax
0.00 : 7ee38: b9 ff ff ff ff mov $0xffffffff,%ecx
0.00 : 7ee3d: 0f 42 c1 cmovb %ecx,%eax
0.00 : 7ee40: c3 retq

Without the debug info in the object code, just the annotated assember is displayed.

To see which events one can trace with, use the perf list command:

./perf list

List of pre-defined events (to be used in -e):

cpu-cycles OR cycles [Hardware event]
instructions [Hardware event]
cache-references [Hardware event]
cache-misses [Hardware event]
branch-instructions OR branches [Hardware event]
branch-misses [Hardware event]
bus-cycles [Hardware event]

cpu-clock [Software event]
task-clock [Software event]
page-faults OR faults [Software event]
minor-faults [Software event]
major-faults [Software event]
context-switches OR cs [Software event]
cpu-migrations OR migrations [Software event]

L1-dcache-loads [Hardware cache event]
L1-dcache-load-misses [Hardware cache event]
...
...
sched:sched_migrate_task [Tracepoint event]
sched:sched_process_free [Tracepoint event]
sched:sched_process_exit [Tracepoint event]
sched:sched_process_wait [Tracepoint event]
sched:sched_process_fork [Tracepoint event]
sched:sched_signal_send [Tracepoint event]

On my system I have over 120 different types of events that can be monitored. One can select events to monitor using the -e event option, e.g.:

./perf stat -e L1-dcache-loads -e instructions dd if=/dev/zero of=/dev/null bs=1M count=1
1+0 records in
1+0 records out
1048576 bytes (1.0 MB) copied, 0.000784806 s, 1.3 GB/s

Performance counter stats for 'dd if=/dev/zero of=/dev/null bs=1M count=1':

1166059 L1-dcache-loads # inf M/sec
4283970 instructions # inf IPC

0.003090599 seconds time elapsed

This is one powerful too! I recommend reading the documentation and trying it out for yourself on a 2.6.31 kernel.

References: http://lkml.org/lkml/2009/8/4/346

Gnome Panel Easter Egg

Found another Gnome Easter Egg today. Right click on an empty region in a gnome panel (top or bottom) and select Properties. Then right click 3 times on the General or Background tabs and you get an animated GEGL appearing thus:


..if you are wondering, the 5 legged goat is the GEGL mascot as created by George Lebl. Weird.

QEMU + EFI BIOS

I've been poking around with the Extensible Firmware Interface (EFI) and discovered that Tristan Gingold has kindly ported an EFI BIOS from the TianoCore project to QEMU.

The EFI tarball at the QEMU website contains an EFI BIOS image and a bootable linux image that uses the elilo boot loader. I simply grabbed the tarball, unpacked it and moved the EFI bios.bin to /usr/share/qemu/bios-efi.bin to make sure I don't get confused between BIOS filenames.

Then I booted using the EFI BIOS and EFI enabled linux disk image:

qemu qemu -bios bios-efi.bin -hda efi.disk

Here is the initial boot screen:



And here's the EFI command prompt:


So if you want to get to play with EFI, here's a great virtualized playground for one to experiment with. Kudos to TianoCore, Tristan Gingold and QEMU!

Suppress 60 second delay in Logout/Restart/Shutdown

With Ubuntu 9.10 Karmic Koala, there is a 60 second confirmation delay when logging out, restarting or shutting down.  This default can be over-ridden to act instantly rather than waiting for a confirmation (and 60 second timeout) by setting the apps/indicator-session/suppress_logout_restart_shutdown boolean to true as follows:

gconftool-2 -s '/apps/indicator-session /suppress_logout_restart_shutdown' --type bool true

(or use gconf-editor to do this if you want to use a GUI based tool).

I suspect the rationale behind the 60 second confirmation delay is just in case one selects logout, restart or shutdown accidentally and in doing so, one has the ability to cancel this before accidentally closing one's session.   So beware if you use this tweak - it assumes you really want to instantly logout, restart or shutdown!