CRiSP, DTrace, and other technobabble

Blowfish

2012-03-14T15:54:00.001-07:00

I've added blowfish support to CRiSP - mainly because I wanted to
(add some basic encryption facilities - reasons are too boring to go
into). Each time I added encryption, its been a nuisance - no
matter whether its my own coding or open source offerings.

Its important to ensure the code compiles identically across all
platforms - any compiler bugs, language undefined behavior, or
word sizes - can mean the difference between a file or block not
being decryptable or checksummable on another platform. This behavior
could go unnoticed for years. E.g. I used to do all my development
on Solaris; after a number of years, I switched to Linux. Linux
radically changes over the course of the years. And it would be "not nice"
to find backups of files unreadable due to such a difference in behavior.

Even high quality open source code can blow up (silently) due to
bugs in compilers or 32bit vs 64bit differences. Fortunately, most
modern code is aware of these things, although many RFCs dont understand
the real world (they provide sample algorithms, which may be proven,
years later, to have buggy example implementations).

Good code comes with self-sanity checking (eg encrypt a block and decrypt
should return the right/same answer). But there is little intermediate
checking. Blowfish does this. Heres some sample code:


  Blowfish_Init (ctx, (unsigned char*)"TESTKEY", 7);
  Blowfish_Encrypt(ctx, &L, &R);
  if ((L & 0xffffffffU) != 0xDF333FD2L || (R & 0xffffffffU) != 0x30A71BB4L) {
  	printf("blowfish_encrypt: L=%lx R=%lx\n", L, R);
	printf("wanted: 0xDF333FD2L 0x30A71BB4L\n");
    	return (-1);
  }

Now, when the assertion fails - tracking down the lines of code which
caused the issue is painful - every line of implementation code will
"look" correct, but subtleties in sign-extension or zero filling or
other ISO/C behavior can make obvious code never show the true issue.

All code should ideally have complete test cases, but you dont really
know what to test for, until much much later, and by then, you may
have even forgotten how it (or your own) code works.

I've recently been fixing annoyances in CRiSP and adding small/minor features.

One issue I was recently tracking down was a memory leak in the MacOS port.
MacOS and the development environment is really nice. Using the GUI (X-Code)
is too heavyweight on my frail Mac, but the command line tools are good.
("leaks" is a very nice tool). I spent a lot of effort tracking down
a leak and fixing a piece of code, only to find that in trying to find
a memory leak, involves the Mac tools *causing* a memory leak. (Effectively
no memory is freed when one of the malloc debug options are turned on;
took me ages to realise I had fixed my leak, but whilst monitoring
for leaks, just showed process size growing as malloc was trying to detect
leaks. Sometimes, its the obvious things).

Whilst on the subject of tools, I finally took the plunge and tried
out Clang (2.9). Its a nice tool for static code analysis - and managed
to uncover a few latent bugs in CRiSP, that I never knew existed. Sometimes
I do like compilers with new features which are helpful. (Many gcc
compiler warnings just generate noise, as does Visual Studio).

Meanwhile...back to figuring out why blowfish is not doing what
is expected with my bits....

[Will resume dtrace shortly - I need to forget how it works, before
tackling the next issue on the table - pid provider].

Post created by CRiSP v10.0.29a-b6234

dtrace4linux - support and issues

2012-02-28T14:30:00.001-08:00

I would like to thank the audience of people using and
trying out the DTrace/Linux port (now hosted at github and
my other tarball downloads).

Can I ask people - when facing compile issues - to ensure they
have all prerequisites before reporting compilation issues.

It is my goal to have DTrace work on all releases of
Linux - both forward and backward releases, but time and space
doesnt permit validating each release (of Linux) - especially
older ones. I do attempt to look at Ubuntu and Fedora (usually after
a prod by the community). I try to avoid downloading the latest
Ubuntu releases until at least a week or two has passed, so that
I can feel more comfortable I am not going to suffer resume+suspend or
wifi or video glitches, like I have done in the past.

One thing I have done brazenly and badly, is keep track of what I
installed on my system in terms of packages. When I first started
DTrace, it was not a virgin Linux distro, but one polluted with my
favorite development packages.

By the time the first DTrace port went out, I couldnt tell the
difference between a virgin install and my own system. Over time, I have
realised this is important for newcomers who download and try out
DTrace, that it works "out of the box", and have attempted to create
scripts (get-deps.pl) to semi-automate updating your system with the
required packages. Even for Fedora and Ubuntu, and 32 and 64 bit variants,
validating that the script works is nearly impossible.

I hope to do better in the future, but there can be no guarantee.

One of the commonest issues reported is missing header files, e.g.
for 32-bit compiles. Even doing a package search using yum or apt-get
or whatever the package installer of choice is called, is a nuisance - as
you get flooded with possible matching libraries. Most of it makes sense
to me, but it likely confuses newcomers to Linux, or people who
are not programmers. Unfortunately, that is life on Linux.

(Maybe I should be adopting a standard RPM format so that the
dependencies can be described properly; something for a different
rainy day).

At the moment, for a short while, I am switching my focus back
to CRiSP - adding features and enhancements; I find it good to switch
back and forth from DTrace to CRiSP, as I sometimes lose focus on
what I am trying to do. DTrace for Linux should be in a good state, and
there are a lot of miniprojects to work on (I had started on the CPC
provider, and theres more SDT probes to work through, along with
refinements on the INSTR provider).

If people find DTrace good for them, feel free to publicise or drop
me a mail, so that I know it is worthwhile.

Post created by CRiSP v10.0.26a-b6206

Doing a dis-service to your fans

2012-02-20T12:34:00.001-08:00

I like Amazon - it has lots of nice features - I wont go into them.
Most people agree, some may disagree.

One feature I like, when I am mentally challenged, is the recommendations.
Based on browsing or purchase history, it learns what you like and suggests
related material. In general, this works really well, and occasionally
pops into view, Music or Videos or Series I may be interested in.

One thing which I find very annoying - and its not Amazons fault - is
the way the music industry takes loyal fans and treats them strangely.

I have listed with Amazon that I have and like Pink Floyd. I am totally
surprised at how many, for example, "Dark Side of the Moon" albums there
are. "Basic", "Advanced", "Intermediate Edition", "With Bells on", "Advanced
sound" (I made these up!). So, my "recommendations" consists of 5 copies
of each of their albums. I have the albums - even a few a couple of times
over.

But I dont know what to do ! I could rate each variant as "I like/5-star",
in which case it might just dig out more versions of the same things or
other music I have, and I end up with no useful recommendations.

I could say "Not interested" to Amazon, but will that mean it thinks I
dislike "Pink Floyd" or will stop showing me the variants across all
types of music.

Oh well. The wonders of technology.

Post created by CRiSP v10.0.26a-b6199

DTrace and the CPC provider

2012-02-14T14:23:00.001-08:00

I've been looking at profiling systems on Linux and other OS's. Its
an interesting landscape. With the advent of ever more powerful
CPUs over the last decade, along with multicore and the impact of
cache misses, its necessary for people to have low level tools
to do performance analysis.

Performance measuring is a large topic - I can only cover it briefly
here. Statistical sampling (similar to classic Unix "prof" and "gprof"),
is great for weeding out hot spots in code. The first time you profile,
its easy to quickly find areas to optimise.

After a while, using those tools runs out of steam. In multithreaded
applications and multicore CPUs, other factors quickly come into play,
e.g. lock contention, cache misses etc.

The Intel and AMD chips provide quite sophisticated counters for measuring
all sorts of things you may never have thought about. Unfortunately,
not only are they different between Intel and AMD, but the counters
supported will vary by chip family. (I dont even know if every
new CPU is a superset of all older ones).

In user space, tools like "oprofile" and "perf" provide a way to gain
access to these counters, and are great for deeper diving into hospots.
You may know 90% of your time is spent in a matrix multiply, but you
may not realise that 50% of that time is wasted in cache-thrashing.

Linux has had a varied past not adopting, and subsequently adopting
profiling subsystems, and although it should be easy, it isnt. The
difficulty of cpu family differences, and complexity due to the
hardware of a system, means that providing a chip-independent API
is difficult.

In recent years, AMD and Intel have provided new monitoring facilities
which aim to allow instruction accurate samples to be made of performance.
(Prior facilities relied on counters and interrupts which couldnt
pinpoint the exact instruction, e.g. where a cache miss occurred).

In Solaris, and DTrace, they added the CPC provider - which allows
probes to be placed based on the counter interrupts. The documentation
is somewhat vague, because everyone is trying hard not to
replicate the Intel/AMD documents which list the counters, since they
evolve so rapidly. The CPC provider is not (currently) in Linux/Dtrace.
Its been on my TODO list and I am just checking it out. It relies on
Solaris handling user level requests and abstracts the CPU away, but,
reading on the web, appears to suffer from inability to handle
the "new style" counters from AMD and Intel.

[I believe that the old style counters are simply counters which can
be set up to generate an interrupt, either on reaching a threshhold
or on a periodic basis, ie sampling based monitoring. The new counters
likely require an area of RAM to fill up, and the code in Solaris,
and probably Linux may not be ready to support this, at least not on older
kernels].

I may experiment with adding a CPC provider, just because I am interested
in seeing these counters and the issues they present.

[I have tried oprofile, and hit problems since it does not work inside
a VM; the newer 'perf' subsystem does appear to work inside a VM, but requires
rebuilding the kernel to enable the subsystem].

Post created by CRiSP v10.0.25a-b6193

github #2

2012-02-08T13:30:00.001-08:00

I guess peoples first reaction to the last post is "Great! Now, what is the
link?!"

https://github.com/dtrace4linux/linux

I did say I was getting to grips with it!

Post created by CRiSP v10.0.25a-b6181

github

2012-02-08T13:29:00.001-08:00

Ive created a new github repository to host the dtrace code.
I will continue to do the tarballs, and people can (hopefully)
watch the github repository to pick up deltas and see change
history.

I did create it the other day, and have to destroy/recreate a couple
of times, due to the script I used to replay the history from all
the tarballs having some blips in them.

I can offer no support on this - hopefully it is helpful, and I am
still getting to grips with it, and git, myself.

This release includes some USDT fixes. But I suspect many more to come!

Post created by CRiSP v10.0.25a-b6181

Its raining.

2012-02-02T15:12:00.001-08:00

No its not raining, but its mighty cold...

Started playing around with USDT - need to iron out some bugs. Alas,
if you run the simple-c example app, and reload the driver, it will
panic the kernel. C'est la vie.

Hope to fix in the next day or two.

Its worth briefly describing "why". When you run an application
which has user space probes (USDT), the application will talk to the
dtrace driver and dynamically create new probes against the PID
of the process and the probes it creates. You can see these by
running "dtrace -l" and diffing a before and after scenario.

Alas, when you terminate the process, the USDT probes arent removed,
and this tickles a problem (which I need to solve).

What dtrace is trying to do is monitor processes as they die, and
removing these stale probes, but it is not.

Now that my other dtrace problems appear to be over (subject to any
naughty regressions I introduce), I can spend a little more time
on USDT and go into more detail.

One area to understand is how a USDT works. I have written about this
before and theres some good web articles on this. The technology is remarkably
simple - but the implementation requires everything to be "just right"
(we are dealing with kernel and user space, after all).

Post created by CRiSP v10.0.23a-b6166

vmalloc_sync_all

2012-01-29T14:21:00.001-08:00

Having "understood" my nested page fault issues, I have been trying
to finalise the code changes. However, any attempt to do so leads me
to a lot of pain.


$ dtrace -n fbt::page_fault:

is a dangerous thing to do - we intercept the page fault handler.
But the page fault handler can be called if a D script tries
to access an unmapped page. We could deter users from putting a probe
on page_fault, but that seems a real shame - thats a very useful
and interesting function to probe.

This works brilliantly on x86/64 systems but fails abysmally on i386.
Having chased the problem down to the issue of kernel page tables
and user process page tables disagreeing about what is "visible", and
the way the kernel does "lazy page table population", its very difficult
to stop a page fault, for instance, in the breakpoint handler.

(We hit the page_fault function, which generates a breakpoint trap to
execute the probe, but whilst processing the breakpoint trap, we induce
a page_fault trap: BOOM!)

I've experimented with various mechanisms to avoid these lazy page
faults. Theres a function in the kernel: vmalloc_sync_all() which
ensures all page tables are in sync with the kernel - so that minor
page faults cannot happen. If I ensure this is called during the driver
load, then the problem of a nested page fault appears to go away.

(This is a better job than the code I wrote which does something similar
but only for specific locations in dtrace itself; vmalloc_sync_all is
a generalised function to sync all page tables of all processes).

So, I will need to recode and remove the cruft from my work-in-progress
dtrace.

(I am trying to track down if vmalloc_sync_all is called by the x86/64
kernel - but not the i386 one; it would certainly explain why I see such
a difference in behavior when tracing the page_fault code).

More later this week if I can successfully resolve this issue, once and
for all.

Post created by CRiSP v10.0.23a-b6159

Impossible progress

2012-01-25T12:56:00.001-08:00

Nigel was asking me today why I was bothering to spend so much
time on a bug which is uninteresting. And if this issue happens
on i386, why dont we see it on x64.

Lets catch up: dtrace, when reloaded on an i386 system, can panic or
hang the system. This doesnt happen on x64.

As much as I like to dismiss i386 as yesterdays technology, it demonstrates
that *something* is wrong. Ignoring this warning sign is perilous.
Before going into the subject in detail: why after a driver load?
Why not half way through debugging your production system?

The underlying scenario may be rare but without the deep understanding,
such a tool can never promote itself in the reliability stakes.

Ok, so lets deep dive. Every process has a page table - which describes
what the process can see. In Linux, process #0 (the 'swapper') also
has a page table, but its a "master page table". It describes what the
kernel can see.

A process is most of the time dealing with its own address space, but
on a system call or interrupt, we are dealing with the kernel. The CPU
contains the circuitry to allow the kernel space to be visible when
the interrupts or system calls happen.

But, how does the kernel map and the per-process map keep in sync? When
you load a device driver (or even plug in a USB drive, for instance),
the kernel will allocate space for the code and data. This belongs to
the swapper/kernel. If whilst your process is executing, the
USB drive generates an interrupt, leading to the USB driver executing,
it will do so in the context of your process page table. You cannot
see this (normally). But those pages are *not* in your page table.

So, as the CPU tries to jump or access this memory, a page fault
will be generated. The page fault handler *IS* in your page table
(as is the whole monolithic kernel). The page fault handler will realise
the page fault happened in kernel space, and will notice that
the swapper page table and your process page table do not agree.
It will copy the offending page table entry from kernel(swapper) to your
process. And the system will continue - as if "by magic". (Function vmalloc_fault()
is the one that does this magic).

Linux/Dtrace is special

Linux/dtrace is very special compared to all other implementations of
dtrace and all other drivers on Linux: it is not only dynamically loaded,
but it contains a page fault handler. (Why? Because when you do silly
things in your D scripts, dtrace wants to prevent you from panicing the
kernel; it has to intercept invalid page faults caused by D scripts;
it doesnt care about normal page faults, and leaves the kernel to do its
stuff).

If the page fault handler is not in the user page table (why should it?
after a module load, it wont be), then we are in dangerous territory.
You cannot simply ignore a "page fault" - you *must* process it. So, heres
the scenario: when dtrace is loaded, it only exists in kernel page
tables - not in any processes page table. Under normal use of dtrace,
invoking probes or syscalls, the act of these probes firing would cause
a page fault to ensure the dtrace code is mapped into the process table
of the process.

What is happening...

After dtrace is loaded, we have two scenarios to consider: system processes
(especially kernel threads, irqbalance, etc) and user procs. The system
processes run in kernel space and have the page fault handler mapped.
(In theory these system procs shouldnt have page faults, but they
might do). The user procs have no knowledge of dtrace, and as they page fault,
the CPU will try to invoke the page fault handler which is not mapped
into the user proc page table. This causes another fault and
we eventually have stack overflow, page table corruption and a double
fault.

The solution

The solution is to ensure that every process has the page fault
handler mapped as the module is loaded. Ive written/borrowed code
to walk the process table, and ensure the page fault handler
is properly "faulted" into the per-process page table.

My first experiments were a failure: even the tiniest of coding blips
will show up as a crash/hang/panic. After validating the code very
carefully: it appears to work.

Forking

When a process forks, the new process gets a copy of the same page
tables as its parent. So, if a process has the page fault handler
mapped, so will its child. I.e. we just need to "seed" every process
on the module load, and we are done.

Why doesnt this happen on x64?

I believe the reason is: probability. It *can* happen but either has not
been observed, or was assumed to be a different bug. I havent
directly measured this (yet) on x64, but all it requires is that the
page where the dtrace page fault handler is loaded into memory,
be mapped into every processes page table *by accident*. This might
happen due to bootup modprobes and other things, or it could be caused
by the layout of the page table directory structure leading to
likelihood of dtrace being on a previously mapped page.
(Maybe even the layout of the ELF format module file might "help").
But on a large memory system, it might not be sufficient and it is likely
the same bug would crash - at the least opportune time.

What next?

Next up is to tidy up the horror of code bodges I have in my VM
and push back to the master dtrace source; see if I can prove it could
be a problem in x64, and ensure the new code is x64 palatable.
(The Linux kernel, in arch/x86/mm/fault.c has two implementations of
vmalloc_fault - one for i386 and one for x64, so I cannot assume the
i386 "fix" will work for x64).

Post created by CRiSP v10.0.22a-b6154

Free advertising! Get CRiSP Now!

2012-01-19T15:16:00.001-08:00

I rarely do what I need to do...push CRiSP into your face.
You are all so busy grabbing copies of dtrace, I can't spoil
your party :-)

After reading about SOPA/PIPA over the last few days and
the current fate of megaupload.com, I thought I would do a search
for "crisp editor crack".

Quite surprised to see how many sites are hosting the software - even
out of date versions. I'm actually quite proud that it should turn up
on every warez site I have never heard of.

I'm looking at one site, where the file size is posted as 58.6MB. Given
that my downloads (admittedly, compressed) are less than 9MB, thats
pretty impressive. I wander what they put into the download.

Its possible some of these are genuine outlets for the software (no
genuine outlet would accept payment, so I am fairly certain this is fake).

I am looking at a URL which looks really nice - nice layout, lots of relevant
decoration, and not very good details. I wont post the site link, except
to say that crisp appears in the domain name.

Its possible this is just a DNS grab and the page is almost certainly
automatically generated.

Its actually impressive the amount of effort people have put into auto
generating fake sites, and CRiSP is in their targets. Thanks! I am impressed.

In case you are interested, just google "crisp editor crack" to get
a feel. The "lifted" text similarities are interesting.

I suspect what you see out there is the union of two things: catalogs
of software - maybe from websites or old shareware type listings, along
with web site generators and automation by cheap labour to flood sites
with everything other than the thing they are purporting to sell. I would
expect all of these to be virus/trojan carrying candidates. One site I am
looking at shows a reasonable filesize, but I cant be bothered to download
and verify the version to see if its real. (The one I am looking at
actually looks really genuine, carrying my partners web logo).

So, if you want to get the best programmers editor ever invented, and
want to change your life, then buy CRiSP N*O*W*! :-)

(I'll update dtrace over the weekend...I know what the problem is, and
the solution is slightly elusive).

Ok, boredom set in ... lets google search "dtrace crack" - not so many
links to choose from. One is a very interesting link, regarding an E-Book by
Jon Haslam. (Apologies to Jon - I dont know him). Sitting on that page
is a lot of links to Playboy/Penthouse forums.

So, even dtrace gets the "Web" treatment.

Post created by CRiSP v10.0.22a-b6154

Update on the impossible

2012-01-17T14:30:00.001-08:00

I've been walking through the scenario of why some kernel
addresses are not visible to some processes. Think of a block of
memory allocated by the kernel for internal use, but triggering
a page fault, e.g. because page is swapped, or hasnt been touched
yet, by the user space.

When the page fault handler is invoked, the address of the buffer
exists only in some process page tables.

Turns out this is a (nice!) clever trick of the kernel. When things
are allocated in the kernel, and should be visible to all processes,
e.g. a driver module or other buffer, when the page fault kicks in,
a check is made if the page is valid in the "master page table".
Process #0, created on kernel boot up, houses the master table.
The currently running process may not have the mapping in place, and instead
of paying a large cost to update all processes page tables to represent
these kernel pages, the page fault handler will update the local process
page table when the fault occurs.

This explains why some processes can see the page in question, and, others
can not.

Bear in mind we are putting in place a page-fault interrupt handler.
This *must*, repeat *MUST* be visible at the time of a page fault, else
we get a cascade of nested page-faults because the handler isnt mapped
in the process page tables.

So, we need to arrange this to be true. At the moment, the options
include: (a) see if anything in the kernel allows us to propagate the
page-table mapping across all procs (nobody else, other than possibly
a Virtualisation guest, such as Xen/VMWare/VirtualBox, is likely to do this),
or, (b) do the hard work myself, (c) move the interrupt handler
into an existing page of mapped memory [hard], or (d) dont patch the
IDT, but patch the existing page fault handler [not sure if this doesnt
just put off the problem].

Let me scrape some cobwebs off my brain...

BTW - heres the relevant comment in kernel/fault.c, function do_page_fault:

        /*
        * We fault-in kernel-space virtual memory on-demand. The
        * 'reference' page table is init_mm.pgd.
        *
        * NOTE! We MUST NOT take any locks for this case. We may
        * be in an interrupt or a critical region, and should
        * only copy the information from the master page table,
        * nothing more.
        *
        * This verifies that the fault happens in kernel space
        * (error_code & 4) == 0, and that the fault was not a
        * protection error (error_code & 9) == 0.
        */

Post created by CRiSP v10.0.22a-b6154

Naughty naughty bug.

2012-01-16T14:49:00.001-08:00

I believe I have finally found / confirmed the root cause of
the "impossible" bug.

Lets go on a journey....

The i386 virtual memory architecture relies on page tables.
Each process has a (complex) array of descriptions for each page.
Each page in the 4GB address space either has an entry, or is missing
an entry. (Each process does not need the full 4MB to describe the
address space, if the process is not using every page of the 4GB space;
4MB is what is needed to describe each and every page for a fat 4GB page).

Now, typically in that 4GB range is user-space (typically everything
below around 3.5GB) and the kernel (everything in the last 0.5GB).
[Details differ in release to release of the kernel].

Now the kernel can see all the user space pages, but typically, the
user space process *cannot* see the kernel pages. (Would be nice if you
could but that would be a security hole). Physical RAM is
mapped so that the kernel can see every page of memory, but the kernel
pages are marked so you can not (in user space) "see them". (With root
access and access to /proc/kmem, you can poke around, but thats not normal
behaviour).

Now, lets consider what happens when a (module) device driver is loaded.
The kernel locates some free memory and loads the image into memory.
The kernel does a lot of housekeeping to link the module into various
lists and expose the /proc, /dev and other entries.

Here it gets interesting...

The driver is loaded into memory - the kernel knows about the memory
before the driver is loaded - its the physical RAM in your box. But
maybe/maybe not - the unallocated "free" memory in the kernel, is not
really addressable - certainly not by user space, and possibly, not
even by the kernel - trying to access free memory would indicate
a rogue pointer or array-out-of-bounds exception. When the kernel
needs a free page, in can ask the kernel allocator for it.

So, this means, if you were to examine the page table for each process
in the system, these free pages are effectively "not there" and this can
help detect rogue pointers and bugs in the kernel.

As the driver is loaded, the pages are flipped to "being there" and visible.
Eg the code for the driver has to be visible to the rest of the kernel,
because you are going to do an open/read/write/close, for example.

Now, from user space - it doesnt know or care about the physical memory
for a driver. You cannot just blindly execute a subroutine in a driver - you
can only get to it, by executing a system call, which takes us from
user space to kernel space, and, once in kernel space, we can see the
code + data for the driver.

The Bombshell

Now consider a driver which embeds its own interrupt routine. When
an interrupt fires, we normally switch to supervisor mode, and the
page where the interrupt routine resides, is visible and executable.

I have been trying to track down a kernel blow up with dtrace, when
its loaded one or more times and a page fault fires. (Only observed
in the i386 kernel, not seen it in the x64 kernel).

When the user space fires a page fault, we switch to supervisor mode
and run the page fault handler. The first bit of this is in the dtrace
driver. If we decide this is not interesting, we jump to the existing kernel
handler.

Half way through the kernel handler, it decides to take a context switch.
(I dont know why - maybe its just being polite, and giving other high
priority tasks a chance to run). As we load the %CR3 register (which points
to the page table directory for the new process), we suddenly lose visibilty
of the dtrace driver. It is no longer visible, in the context of that
process, *EVEN FROM SUPERVISOR MODE*.

That new process which just got the CPU takes a page-fault and *BANG*!
GAME OVER!

The page fault handler is no longer visible. In fact, trying to take
the interrupt fires a page fault exception, which in turn fires a page
fault exception. The stack overflows and the CPU merrily trundles along
overwriting the entirety of memory until it shoots both its feet off.
(Eg, it starts to overwrite the page table itself or some other important
structure). I strongly suspect that using the *page table* as a *stack*
is what causing the CPU to triple fault and for VMWare and VirtualBox to
report an unexpected unrecoverable event has happened, and shuts down the VM.

Eh? Whaddya say?

The evidence suggests that when a driver is loaded into kernel memory,
ONLY SOME PROCESSES HAVE IT MAPPED INTO THEIR PAGE TABLE.

I did an experiment: I wrote some kernel code to let me probe
each process on the system, to see if that process could see, in kernel
space, a specific address. I tried a kernel address and that was fine (eg sys_open).
I tried the dtrace interrupt (dtrace_page_fault), and it wasnt. I
loaded a random other driver, and confirmed the same.

So, lets revisit. When a driver is loaded into kernel memory - it
is touch and go as to whether the driver should exist in the page
tables of all processes in the system. Loading a driver could cause a lot
of page table updates, as each processes page table would need to be
updated to reflect the mappings. Or, instead the kernel might decide its
not worth the bother: user space cannot access system space, except via
a trap into the kernel via a syscall or interrupt.

So, why do half of the procs in the system have the driver loaded and the
others do not?

Heres my guess: when a driver is loaded into memory at least one
page table needs to be modified. This is a special page table which
belongs to process zero (the swapper process). [A data structure
called the swapper_pg_dir holds the kernel page table]. Under normal
circumstances, every time a new process is created, it is a fork/clone
of an existing process, so that new process gets a copy of the kernel
page tables.

But loading a driver means we cause a "warp" effect - the kernel gets
the new mappings, but some/none of the user procs do not get this.

The solution

Is this a bug? Is this a misinterpretation by me? It feels like a bug.
Maybe the dtrace driver is miscompiled and I havent put the
interrupt codes into the right ELF section (so I will go and check).

If its not a compile/declaration problem, then either I need to
update every processes page table to see the driver pages, or find
a way to ensure that a kmalloc()ed page is visible by all processes.

The evidence

Heres some evidence to support my findings. I invoke a kernel
function to probe three addresses: static kernel function, dtrace page
fault handler, "other" loadable module:


...
5.568007271 #0 1490:1294 d87fa000
5.568007271 #0 1490:     lookup1: c182009c 1
5.568007271 #0 1490:     lookup2: ebc236d0 1
5.568007271 #0 1490:     lookup3: 00000000 3
5.568007271 #0 1490:1489 d86ef000
5.568007271 #0 1490:     lookup1: c182009c 1
5.568007271 #0 1490:     lookup2: ebc236d0 1
5.568007271 #0 1490:     lookup3: eb0c52b4 1
...

"1490" is the PID of the process invoking the tracing. The first entry
is for pid 1294. This PID can see the kernel function and the dtrace function,
but not the "other" driver. Pid 1489 can see all three addresses I
specified. Theres no real logic to why pid 1294 cannot see the new
driver.


root      1294     1  0 21:38 ?        00:00:00 /usr/sbin/console-kit-daemon --no-daemon
fox       1489  1289  0 21:38 ?        00:00:03 sshd: fox@pts/1

Heres the kernel code, in case anyone is interested, which
dumps the output:


void xx_procs(void)                                                           
{       struct task_struct *t;

// hack to call a GPL function in the kernel
pte_t *(*lookup_address)(unsigned long, unsigned int *) = 0xc10277f0;
	int     level = -1;
	pte_t   *p;

	printk("process list:\n");
	p = lookup_address(0xc10277f0, &level);
	printk("  lookup: %p %d\n", p, level);                                
        for_each_process(t) {                                                 
                struct mm_struct *mm;                                         
                struct vm_area_struct *vma;
                
                printk("%d %p\n", t->pid, t->mm ? t->mm->pgd : NULL);
                if ((mm = t->mm) == NULL)
                      continue;
                
                // lookup_address1() is the same as the kernels
                // lookup_address() - but private copy to allow a 
                // procs mm_struct to be passed so we can probe another
                // processes page table.
                
                // random kernel address
                p = lookup_address1(mm, 0xc10277f0, &level);
                printk("     lookup1: %p %d\n", p, level);
                
                p = lookup_address1(mm, dtrace_page_fault, &level);
                printk("     lookup2: %p %d\n", p, level);
                
                // random "other" module address, gained from /proc/modules
                p = lookup_address1(mm, 0xeecad000, &level);
                printk("     lookup3: %p %d\n", p, level);
        }
}

Post created by CRiSP v10.0.22a-b6154

Dtrace progress on the impossible

2012-01-15T02:06:00.001-08:00

Since using VMWare and the gdb debugger to reliably debug this issue,
I have an update.

It turns out that as soon as the page-fault interrupt handler is enabled,
when we take the first page fault interrupt, we pass it over to the kernel
default handler. On return from the kernel, the page where the
dtrace handler is located is no longer mapped in the page tables
(for some reason).

On the next interrupt, the CPU jumps to a non-existant page, resulting
in a nested page fault interrupt. This continues for a few thousand
iterations, until the kernel stack blasts through something, leading to
a double fault.

Interesting that the kernel stack contains thousands of copies
of the same data (pushing of the page fault code, CS:IP and flags
registers).

gdb under VMWare player lets me set hardware breakpoints, so I can
single step the kernel page fault handler. I've just had my first
attempt, but unfortunately, maybe because of how long I took, the
page fault handler decided to reschedule a different process to run,
so I lost control.

Its truly great single stepping whilst gdb is showing me the line of
code we are on.

Lets see if I can to what caused the mapping to disappear.

More later.

Post created by CRiSP v10.0.22a-b6154

VMWare Player .. nice

2012-01-14T10:14:00.001-08:00

I used to use VMWare server - quite a few years ago. I really liked it.
But I got fed up with the server product lagging kernel development.
New Linux kernels would come out and either I, or someone else, would
have to figure out the compile-time changes for the drivers.

VMWare created the Player product - which could be used for running VMs
but not creating them. I have up with VMWare workstation.

That was a few years ago.

Today, I installed VMWare Player 4.0 - and it works as expected. Its nice
to come to it after a few years of non-use. It seems highly reliable and
works.

So, I transferred my Ubuntu 11.10 i386 VM from VirtualBox to VMWare Player.
A bit of googling showed me how to convert the disk image.

The VM came up fine. I had a few issues with the network card. My
kernel didnt have the driver - I had disabled as much as possible when
creating a custom kernel, so spent a little while trying to find the
PCNET32 driver. That resolved, I could remote login.

So - now time to try dtrace: pretty much the same results as VirtualBox.
Some small difference - occasionally when VB would hit the double fault
issue, the screen would frantically scroll for 5-10s until the VM gave
up and hung (hard). Doing the same on Player - it will scroll continously.
There appears to be an emulation difference, which, by the looks of
it, is that VB isnt playing as well in the face of double faults.

All this would be boring. But googling for 'vmware debugger' led me to
a page which shows how to enable local gdb debugging of the VM guest.
Using TCP rather than the silly serial port emulation of classic kgdb
setups in the kernel.

So, I tried it. The first thing to note is: it just worked. gdb got
a breakpoint in the native_safe_halt function in the kernel. Whats
interesting is that when a breakpoint is hit, you get a big "Pause" bitmap
slap in the middle of the video console. If you hit ^C in the gdb to regain
control, or we hit a panic, the pause bitmap becomes visible and you know
you have stopped the VM.

The gdb debugger seems more resilient to debugging the doublefault.

Heres a fragment of the stack trace from gdb:


.....
#253 0xc1004adb in show_registers (regs=0xc1732a6c)
    at arch/x86/kernel/dumpstack_32.c:106
#254 0xc1460113 in __die (str=0xc15865f6 "general protection fault",
    regs=0xc1732a6c, err=0) at arch/x86/kernel/dumpstack.c:275
#255 0xc10058c2 in die (str=0xc15865f6 "general protection fault",
    regs=0xc1732a6c, err=0) at arch/x86/kernel/dumpstack.c:308
#256 0xc145f836 in do_general_protection (regs=0xc1732a6c, error_code=0)
    at arch/x86/kernel/traps.c:402
#257 
#258 0xc1048c04 in vprintk (
    fmt=0xc158f150 "<0>PANIC: double fault, gdt at %08lx [%d bytes]\n",
    args=0xc1732b38 "") at kernel/printk.c:827
#259 0xc1456956 in printk (
    fmt=0xc158f150 "<0>PANIC: double fault, gdt at %08lx [%d bytes]\n")
    at kernel/printk.c:750
#260 0xc1021bee in doublefault_fn () at arch/x86/kernel/doublefault_32.c:26
#261 0x00000000 in ?? ()

So - its good that I am seeing the same thing with VMware, and I have
a new "debug" route to try and diagnose.

Just need to figure out who is at fault. It has to be "me". I hope its not
the Virtual emulation (VB or Player). I hope its not a CPU bug. I hope
its not the Linux kernel.

Post created by CRiSP v10.0.22a-b6154

The 'Great Bug' of 2011/2012

2012-01-14T02:19:00.001-08:00

In my recent blog postings, I wrote about the "most difficult bug in the
world" to resolve. On i386, loading dtrace and patching the page fault
interrupt vector would panic/hang/double fault the kernel.

I have spent the last few weeks trying absolutely everything conceivable,
to no avail. When faced with such a bug - one has to try everything, but,
in the corner of your mind, you know that eventually, it may not
be the place you are looking at - which is why it can be so elusive.

Lets recall the issue: when loading the driver, it works - the driver
loads and full functionality is available. If we remove the driver, the
system still works. If we reload the driver again, we get panics, where
even the kernel stack dumper panics the kernel. Evidence shows corrupt
page tables or interrupt stacks, and, using the VirtualBox debugger, we
can probe (a little) to see what is happening in the VM.

Removing the providers in dtrace, removing calls to activate timers and
just about removing anything that does real work, shows the problem to
remain. The interrupt patching code was modified to be more careful
about how it does the job. The key difference between "it works very
well" and it "reliably crashes" is patching the page-fault vector (0x0E).

Even if the page-fault handler in dtrace is modified to be a jump to
the original vector - no touching of registers, the problem persists.

I have modified dtrace to avoid touching the page fault vector, and
instead, allow me to on-demand update the vector to the new or
old interrupt location with an "echo" statement to the /proc/dtrace/trace
device.

This is useful - because it helps to isolate all the things that happen
when a driver is loaded, from the fault at hand.

Still: its erratic. I have times where I can reload the driver and
patch the vector zillions of times, and others where, on the 2nd time,
we go bang.

I've been studying in more detail the TSS register in the cpu and better
understanding how Linux and x86 in general handles nested interrupts,
and handling multiple interrupt stacks. I have been using kgdb and the
kdebug debugger in the kernel, along with the VirtualBox debugger.

Working Backwards

Nothing works deterministically: it either works brilliantly or fails
dysmally.

Lets take a trip to a different place: lets work backwards.
A "double-fault" interrupt is caused because an interrupt has effectively
raised a general-protection fault (invalid segment selector, invalid
address, page-fault, etc). So how can this happen? Well, a likely scenario
is that the segment registers (%GS, %FS, %DS, %ES) are wrong.

There are really two scenarios for a page fault: it either happens in
user space or kernel space. A user page fault might happen because
reference to an mmapped area has yet to page-fault-in the page just
touched. Another case for user page faults is the stack - as the level
of nesting in an application increases, lower pages in the stack may
need to be allocated/mapped.

User page faults are typically *rare*, especially on a small system
because the working set can be mapped into the address space on startup.

Kernel faults are most common (are they?!), e.g. read() into a large
buffer which has been mmap()ed could cause this.

I may look at which faults really are most common. (Nothing in the kernel
tracks the types of faults [I think]). The difference is the segment
registers: when a user app faults, the DS/ES/CS registers will point to user
space, so the interrupt routine needs to modify these to point to the
kernel address space. (Otherwise, things like referring to a .data or .bss
object, in C, will generate a fault). If we trap from the kernel, then these
registers are already the correct values.

[Theres more complication here - the Linux interrupt vectors handle
nested interrupts, double faults, NMI and other things, but lets keep it
simple for now]

Now, the dtrace page fault handler keeps a count of how many interrupts
it sees (/proc/dtrace/stats). So, when it works, we can see it working
reliably. The figures are actually lower than I expect, but that may be
the kernel doing a good job of typically preloading new processes to
minimize page faults, so, I actually have to work hard to generate a high
degree of page faults).

So, when we have a double fault - we know an interrupt routine had
a problem. The trouble is, in this case, we dont know which interrupt
routine caused the original violation, because the double-fault handler
generates a new fault. (I think the i386 kernel code is broken - it
is walking a stack and the cpu registers are not consistent; i see streams
of stack dumps where each stack dump is causing another, nested stack
dump, and it all scrolls off the screen. I have used virtualbox debugger
to see the true stack, and this is only partially helpful).

When a nested fault occurs, the CPU will switch from the offending stack
to a new stack, set up just for this purpose. This is a brilliant feature
but its causing me a problem as I am having trouble finding the original
offending stack.

Lets patch the kernel

Ok, so we know something is wrong. Maybe we can detect the issue before
it happens and get a deterministic panic. I modified the code in the
kernel - just before we dispatch to a new process, to validate the
page-table, and also, to monitor the low water mark of the kernel
stack. Suggestions on google are that the symptoms I am seeing are
due to stack overflow. Neither of the mods I have made have helped.
Typically, the kernel will use about 2K of the 4K stack space available
to it - it rarely gets close to 3K, so I dont believe we are overloading
the stack and corrupting key data structures.

Lets give up?

I refuse to give up on this. I am mentally walking thru kernel code and
scenarios, trying to conjure up the "it doesnt happen often" case, to detect
what can be happening.

Today, I was wondering if, in the VM, we give it a nice round number
of memory or an odd number - whether this could impact. I typically give
my VM about 730MB of memory. I tried giving it exactly 256MB and it worked
perfectly! Briliant!. Rebooted and tried again at 256MB, and it failed.

Theres almost a flavor to the underlying problem. Often, I am getting a scenario
where it works for extended periods of time: I cannot crash the machine.
Other times, it crashes exactly on the second load (sometimes, even the first
load, although this is rare).

Its almost as if the problem is to do with exactly what is allocated
in memory. I tried a test by filling memory with a large file (full of
zeros), and checking to see if the file was mutating. (Maybe the interrupt
routine was firing with incorrect DS/ES registers and attempts to increment
a counter was randomly patching a random page in memory - that would exactly
explain the kind of problem I am seeing).

So, so far: nothing. No deterministic testing is locating the root cause
of this fault. (I am also wondering if VirtualBox is broken - I have
seen the many bug reports and complaints about VB on the web, but I have
no evidence that the bugs are my problem. I must get emu or VMware up and
running to do side-by-side comparisons).

Post created by CRiSP v10.0.22a-b6154

More on the impossible

2012-01-08T13:47:00.001-08:00

I wrote last time about the worst bug to try and diagnose, namely
one where we lose the page table or GDT or both. Doing so can result
in a double or triple fault, and no way to figure out where you came from.

In user space, a jump to a virtual method (which is in essence a call
to a function via a level of indirection), can mean the PC is set to zero,
and, is similar, in that it is annoying to not know where you came from.
But the fact the program counter is zero tells you that you went through
a null pointer.

So, where am I solving the "impossible"? Not much further forward.
I have been using the VirtualBox debugger - but it is very broken and
pathetic. You cannot set breakpoints or hardware breakpoints if
using the VT-x/AMD-V virtualisation acceleration. If you turn these
off, you can, except the semantics of breakpoints breaks the guest
operating system. In addition, writing to guest CPU registers is not
implemented.

I took a quick look at qemu, but I didnt like what I found -- I prefer
a CLI in general, but for VM guests, I prefer a GUI to get me comfortable.
The GUIs on Linux are very ugly and amateurish which didnt instill confidence
in me. (I know, this is unfair of me). I may try again in the future.

I went back to kgdb - at least this let me set breakpoints and hardware
breakpoints, which is useful. But the process of using kgdb is very
clunky - the guest and remote debugger get out of sync on the comms protocol.
In any case, hitting the bug I am interested in didnt help much, with kgdb.
I could break in the doublefault_fn function, but we couldnt really
figure out where we had come from.

I modified dtrace to allow access to the GDT and IDT via
/proc/dtrace/gdt and /proc/dtrace/idt. (Not really needed, but useful
for validating that these data structures are correct).

What I am finding is that on a double trace fault, there is a suggestion
that the original offending kernel stack for a process has been set to
all zeroes. When the kernel tries to dereference an argument on the
stack, or return from the offending function, it generates a GPF, which
in turn generates a double-fault. (I'm not totally sure of this - a GPF
wouldnt normally generate a double-fault, unless the GDT, page table
or IDT were screwed up).

Lets just revisit what I am doing: having cut down dtrace to a minimalist
shell, we can override entry IDT[14], which is the page-table vector
entry. If we put in the actual value which is there already, everything is
fine.

If we modify the entry to point to our interrupt routine, and make
our interrupt routine simply jump to the original kernel routine, at
some time after this change (could be instantaneous to a minute later),
we crash the kernel. It feels like a few pages of the kernel got overwritten,
e.g. memset(random-ptr, 0, PAGE_SIZE). But tracking this down is
nearly impossible.

I have been adding debug code to the kernel source to try and do extra
validation (eg in the scheduler, just before the context switch occurs),
but this hasnt proven fruitful so far.

Its almost like looking for a root kit in the kernel - I almost wander
if the kernel has some tamper-resist code in there (it does, but not like
this).

I need to somehow checksum the entirety of RAM and look for something
unexpected to happen, but doing this isnt viable. RAM and processes are
changing all the time. Process creation complicates things - every fork()
generates a new process with a new kernel stack. I need to keep walking
all processes kernel stacks to detect corruption, before we switch to the
process.

I am running on a single-CPU guest, to avoid the complexity of multi cpu
operations. What I cannot determine is if something is being corrupted by
virtue of writing to the IDT, or a long time after.

Alas, google searching hasnt been helpful - the symptom and problem is
very unique (I am not writing a rootkit, although dtrace looks an awfully
lot like a rootkit in terms of what it does), and I am not booting up a
new operating system. Nobody describes the scenario of modifying an
in-use IDT and the things that can go wrong. (I did find two links,
quoted in a couple of posts ago).

Next is to try disabling dtrace's timer code - maybe that is causing
non-deterministic behavior.

Post created by CRiSP v10.0.22a-b6150

Debugging with VirtualBox

2012-01-04T14:22:00.001-08:00

Earlier, I wrote about the worst type of bug in the world -
one where we smash the internal CPU registers so badly, that nothing
recovers - no interrupts, no double/triple faults.

Ive been experimenting with the VirtualBox debugger, and its very
nice, albeit a little basic. Anyone interested in playing with this will
need to read the manual.

But heres an illustration of a CPU-smashing bug.

See

https://www.virtualbox.org/manual/ch08.html#vboxmanage-debugvm

If I run the following command, I can get a complete dump
of all registers in the CPU in the VM guest:


$ VBoxManage debugvm  Ubuntu-11.10-i386 getregisters all | tee /tmp/reg
cpu0.rax               = 0x0000000000000000
cpu0.rcx               = 0x0000000000000000
cpu0.rdx               = 0x0000000000000000
cpu0.rbx               = 0x00000000c1644000
cpu0.rsp               = 0x00000000c1645f80
cpu0.rbp               = 0x00000000c1645f98
cpu0.rsi               = 0x00000000c1698fb8
cpu0.rdi               = 0x000000004fcb43de
cpu0.r8                = 0x0000000000000000
...

Now, I save this to a file, and then cause the host to crash. We
dump the registers again and now we can diff the results. We expect
to see lots of differences, but heres some of the key elements:


33,36c33,36
> cpu0.gs                = 0x00e0
> cpu0.gs_attr           = 0x00004091
> cpu0.gs_base           = 0x00000000ecc05c00
> cpu0.gs_lim            = 0x00000018
---
> cpu0.gs                = 0x0000
> cpu0.gs_attr           = 0x00010000
> cpu0.gs_base           = 0x0000000000000000
> cpu0.gs_lim            = 0x00000000

Not the GS register is smashed in the diff. Theres no base address for
the segment definitions, so any code trying to use GS will cause a
double/triple fault. Thats not good for the kernel.


98,99c98,99
> cpu0.cr2               = 0x00000000b78a0000
> cpu0.cr3               = 0x000000002a945000
---
> cpu0.cr2               = 0x00000000c1647040
> cpu0.cr3               = 0x0000000001748000
114c114
> cpu0.tsc               = 0x89fd0226
---
> cpu0.tsc               = 0x02307c70
119c119
> cpu0.msr_gs_base       = 0x00000000ecc05c00
---
> cpu0.msr_gs_base       = 0x0000000000000000

Register CR3 is the page table base address. In the crashed machine, CR3
looks "wrong". And the interactive VirtualBox debugger wont get very far with this
wrong value as it needs the page tables to map virtual addresses
to physical ones.

Likewise, the msr_gs_base (which is an internal register which holds
the place where the GS register is taken from, on a kernel switch) seems
corrupt.

This is why my guest is a smashed VM.

But, alas, I dont know whats causing this.

Still investigating....

Post created by CRiSP v10.0.21a-b6145

Is that the worst you can do ?

2012-01-04T13:05:00.001-08:00

Whats the worst thing you can do to a CPU whilst executing code?

How about a buffer overflow .. overwriting beyond the end of a buffer.
Very soon a segmentation violation (or GPF) will happen, and the application
will terminate, or try to recover.

How about inside the kernel? Well, pretty much the same thing.

The x86 architecture is well thought out. When some form of memory
access goes awry, an interrupt is generated (technically a 'fault' or 'trap'),
and the kernel will attempt to recover from this.

The act of taking an interrupt involves pushing the current program counter
on the stack, and jumping to a predefined location.

Great. So - whether a GPF occurs in user space or kernel space, something
will happen. This is either recoverable, or a panic/blue-screen can
happen if the kernel doesnt know what to do.

The predefined location is setup in a table called the IDT (Interrupt
Descriptor Table).

If the interrupt to handle a GPF takes a fault itself, the system
will generate a double-fault. Double-faults are very rare. (GPFs are
very common, and can be caused under normal circumstances via memory
mapped/anonymous memory, as pages are faulted into existence).

A double fault typically indicates a flaw in a driver and can
be caused by using an invalid pointer or a stack exception in an
existing interrupt.

A triple fault is what can happen if a double fault generates an
exception. This would indicate the double-fault handling code hit
an unexpected condition. On the Intel/AMD architectures, a triple fault
will typically reset and reboot the CPU.

Normally, the kernel and CPU operate together on some very key data
structures. We mentioned the IDT, above. Theres also the GDT - which describes
how segments of memory map to real memory. And then theres the LDT - which
is a per-process view of memory. Corrupting any of these can
lead to double/triple fault behavior.

But theres another data structure: the page table directory. If the
page table is corrupted then all bets are off. The page table can be used to
indicate what blocks of memory are present/not-present in the system and
is the mechanism for virtual memory support. If the page table were
corrupt, then an application would generate a page fault interrupt and the
kernel would quickly shut down the offending process.

But what if the kernel version of the page table were corrupt? On an
interrupt, the CPU wouldnt be able to access the code to execute the
interrupt handler, which in turn would lead to a double fault, and thence
to a triple fault.

All of this is well documented on the web.

But I am having a hard time with dtrace on i386 architectures. After
loading dtrace, and then removing from the system, on a subsequent
reload of the driver, the system crashes/hangs. Most of the time there
is no output on the console; when there is output on the console,
its confused and corrupted. Which indicates that one of the
key data structures in the kernel is corrupt (IDT, Page Tables or GDT).

And, because of this, nearly impossible to debug. Nothing in the kernel
can help debug this scenario - we cannot print or signal what has happened
or where we were prior to the crash.

At the moment I am using the VirtualBox debugger to poke around after
a crash, but the debugger wont let me examine memory exactly because the
page table is corrupt (or the CR3 register is corrupt, but I cannot
tell the difference; CR3 is the register which points to the start
of the page table).

So, this is the worst bug to resolve - no kernel debugger, printk statements
or something in the kernel will help find the cause of the strange hang.
(Strangely, this problem does not exist in in the 64b kernel).

Post created by CRiSP v10.0.21a-b6145

Happy New Year Dtrace...You ruined my Christmas

2011-12-31T09:05:00.001-08:00

I have just spent the last few days tracking down a strange
issue. Having fixed up dtrace to work on Ubuntu 11.10/i386, I found
that reloading the driver would hang/crash the kernel.

This was related to the page-fault interrupt vector. If that was
disabled, then all was well.

Strange. I dont recall this error before....

Although most recent work has been on the 64b version of dtrace,
I had assumed the 32b was in sync and all-was-well. But not so.

Its an interesting trail....I thought the driver reload/reload/...
cycle was fixed. It works well on 64b kernel, but not on the 32b one.

After a lot of searching, and narrowing the problem down to the
page fault interrupt vector, I checked on my rock-solid Ubuntu 8.04
(2.6.28 kernel). And hit the same problem: namely a double (or even
single) driver reload would hang the system.

I spent a lot of time on the Ubuntu 11.10 kernel - the driver
would hang the kernel on the first load after bootup. I eventually
was tinkering with GRUB and turning off the splash screen, and got
to a point where the first load would work, the 2nd would hang.

Prior to this point - I had no way to debug the code. Any attempt
to leave the page fault vector modification in place would hang the
kernel .. or cause a panic in printk(). I eventually considered this
to be a problem where the segment registers were not setup properly.
(The kernel uses the segment registers to access kernel data and
per-cpu items, so, if these are incorrect on a page fault, you arent
going very far). I even cut/pasted the existing kernel assembler code
for page_fault, but had a lot of problems getting something repeatable.

Whilst investigating this, I had to do a lot of "mind-experiments": what
was the CPU up to? Why was it having a hard time?

Well, what I realised is a number of things:

On a SMP system, each CPU has its own IDT register - set to the same
location in memory. We might patch the interrupt vector table, but
there was no guarantee the other CPUs would see these changes atomically.
In addition CPU caching might cause the other cpus to see the old
values of these interrupt vectors, until enough time had passed to
force cache line flushing.

Bear in mind, we are patching vectors in a table, so, the CPU may not
know we had done this. For all we know, the CPU may have cached the
page_fault vector and may not notice our changes. Or, ditto for the other
cpus.

So, google to rescue us. After a short while, I found these two
links:

http://stackoverflow.com/questions/2497919/changing-the-interrupt-descriptor-table

http://www.codeproject.com/KB/system/soviet_direct_hooking.aspx

The second link hinted at my problem: if you randomly change the interrupt
vector table, then expect problems. The codeproject link didnt suggest
an explanation, but hinted that the way forward was to create a new IDT,
copy the old table to the temp, switch the CPUs away, make the updates, then
switch back.

The first link confirmed this. (Interestingly, the second link is for
info on a Windows kernel, but the first link echoed the same sentiment
on Linux).

After a lot of fine-tuning the code and cleaning up, it now works !

The trick is to switch the CPUs away whilst updating the vector
table, and switch back when the updates are done. Also, to do
the same during the driver teardown code, so we can load/unload
repeatedly.

On the way, I added a /proc/dtrace/idt driver so its easier to visually
see the raw interrupt descriptor table.

One interesting issue here is why the 64b driver didnt suffer the same
problems? It feels like we hit a CPU bug/errata in this area, and
the 64b CPU mode does not suffer this problem (or, the size of the
64b IDT vector entries "move" the problem around).

Now I just need to tidy up the code and release ... the last release
of 2011.

Happy new year.

Post created by CRiSP v10.0.21a-b6142

Dtrace / Ubuntu 11.10/i686

2011-12-27T10:13:00.001-08:00

Spent some time over Xmas adding a new provider (the 'proc' provider)
which is a simple layering on the existing providers, and provides
easy access to process creation/termination. Its unfinished.

I was asked about some compile errors on Ubuntu 11.10/i686 and
was confident there was no issue here.

What I hit upon really made my stomach churn. Firstly, a simple
error stopped compilation because of something not quit right in
GCC. That was easily fixed.

But no /usr/include/sys directory was a stunning shock. That means
most apps are not going to compile. Period. Scanning google showed
that the error was common, but yet I couldnt find a solution,
that didnt involve a "hack". The hack is to manually symlink
/usr/include/i386-linux-gnu/sys to /usr/include/sys.

Strange, because the 64bit release works perfectly.

But then, the next horror story is that dtrace will quite
happily crash the kernel. There seems to be possibly two
avenues of investigation. Firstly, the kernel is complaining about
stack overflow, which means they built the kernel with tiny (4k? 8k?)
stacks, and could be a problem for dtrace. If this is the case, we will
need to switch to our own stacks; not had to do that before.

The other issue, which might be related, is that the interrupt
handler does not work. Again, this could be related .. if we
blow a stack then we will corrupt whatever is abutting our stack
pages, and all bets are off. (I am getting quite reliable VirtualBox /
Guru Meditation dialogs, which is a sure sign of a double or triple fault,
again, hinting at bad karma with the stacks).

So, off to go fix the i386 build. (The Ubuntu 8.04 release
works really nicely, as a BTW).

Post created by CRiSP v10.0.21a-b6142

dtrace update

2011-12-22T14:20:00.001-08:00

Just released a new version of dtrace. This should fix a couple of issues.

The first was that 64b ELF binaries using user-space (USDT) probes
couldnt correctly notify the kernel of the probe points. This was
tracked down to a strange issue in the libelf binary where attempts
to update the relocatable symbol table entries weren't being committed
to the output file. I also found a lack of symmetry in the Solaris
code, which probably worked because the Solaris libelf routines
allow for a problem of storing a RELA entry into a REL slot.

The second issue was that user space breakpoints being ignored
by the interrupt routines by a previous cleanup/change. i386 and
x64 are now in sync.

Heres an example of the sample program demonstrating the USDT
probes in action:

In one terminal, we run the simple-c tool:


$ build/simple-c
__SUNW_dof header:
dofh_flags     00000000
dofh_hdrsize   00000040
dofh_secsize   00000020
dofh_secnum    00000009
dofh_secoff    0x40
dofh_loadsz    0x270
dofh_filesz    0x400
0: 0008 0001 0001 0000 0000023c 00000034
1: 0010 0008 0001 0030 00000160 00000060
2: 0011 0001 0001 0001 000001c0 00000002
3: 0012 0004 0001 0004 000001c4 0000000c
4: 000f 0004 0001 0000 000001d0 0000002c
5: 000a 0008 0001 0018 00000200 00000030
6: 000c 0004 0001 0000 00000230 0000000c
7: 0001 0001 0000 0000 00000270 0000000a
8: 0014 0001 0000 0000 0000027a 00000186
PID:14632 0: here on line 93: crc=00008998
PID:14632 here on line 95
PID:14632 here on line 97
PID:14632 here on line 99
PID:14632 1: here on line 93: crc=00008998
PID:14632 here on line 95
PID:14632 here on line 97
PID:14632 here on line 99
PID:14632 2: here on line 93: crc=00008a4c
PID:14632 here on line 95
PID:14632 here on line 97
PID:14632 here on line 99
PID:14632 3: here on line 93: crc=00008a4c
PID:14632 here on line 95
PID:14632 here on line 97
PID:14632 here on line 99
PID:14632 4: here on line 93: crc=00008a4c
PID:14632 here on line 95
PID:14632 here on line 97
PID:14632 here on line 99
...

Ignore the dof dump at the top - that was for my benefit to debug
what was being sent to the kernel. Note the "here on line" messages, and
the CRC. As the app started, but before the USDT probes were enabled, the
code segment had one checksum. After I started dtrace in another window,
the checksum changes, (which proves something happened to the code segment,
namely the NOPs are replaced by breakpoint instructions):


$ dtrace -n :simple-c::
dtrace: description ':simple-c::' matched 2 probes
CPU     ID                    FUNCTION:NAME
  1 312224                    main:saw-line
  1 312225                    main:saw-word
  1 312225                    main:saw-word
  1 312224                    main:saw-line
  1 312225                    main:saw-word
  1 312225                    main:saw-word
  ....

Theres still some problems to resolve. When the simple app terminates, the
probes are left active. We need to detect process exit (or exec) and
remove the probes.

Theres some more examples/details on dtrace.org on USDT, here:

http://dtrace.org/blogs/dap/2011/12/13/usdt-providers-redux/

Post created by CRiSP v10.0.21a-b6141

Your dtrace fell into my dtrace :-)

2011-12-17T05:53:00.001-08:00

Having validated we have the dtrace print() function, we can
do a CTF-style structure dump print.

You are partially on your own - go find a structure to print out.
(You can't have mine, because its mine! All mine!)

This simple example shows the ctf-style print in action:

Reference: Eric Schrocks dtrace blog:

http://dtrace.org/blogs/eschrock/2011/10/26/your-mdb-fell-into-my-dtrace/



$ build/dtrace -n 'BEGIN{print(*((struct file *)0xfff
fffff81a156a0)); exit(0);}'
dtrace: description 'BEGIN' matched 1 probe
CPU     ID                    FUNCTION:NAME
  1      1                           :BEGIN struct file {
    union f_u = {
        struct list_head fu_list = {
            struct list_head *next = 0
            struct list_head *prev = 0
        }
        struct rcu_head fu_rcuhead = {
            struct rcu_head *next = 0
            void (*)() func = 0
        }
    }
    struct path f_path = {
        struct vfsmount *mnt = 0
        struct dentry *dentry = 0
    }
    const struct file_operations *f_op = 0xcf
    spinlock_t f_lock = {
        union  {
            struct raw_spinlock rlock = {
                arch_spinlock_t raw_lock = {
                    unsigned int slock = 0
                }
            }
        }
    }
    int f_sb_list_cpu = 0
    atomic_long_t f_count = {
        long counter = 0
    }
    unsigned int f_flags = 0
    fmode_t f_mode = 0
    loff_t f_pos = 0
    struct fown_struct f_owner = {
        rwlock_t lock = {
            arch_rwlock_t raw_lock = {
                s32 lock = 0
                s32 write = 0
            }
        }
        struct pid *pid = 0
        enum pid_type pid_type = PIDTYPE_PID
        uid_t uid = 0
        uid_t euid = 0
        int signum = 0
    }
    const struct cred *f_cred = 0xffffffff810267c4
    struct file_ra_state f_ra = {
        unsigned long start = 0
        unsigned int size = 0x17d436
        unsigned int async_size = 0x8
        unsigned int ra_pages = 0x3e8
        unsigned int mmap_miss = 0
        loff_t prev_pos = 0x200fffd058
    }
    u64 f_version = 0x700000000
    void *f_security = 0
    void *private_data = 0xffffffff810267dd
    struct list_head f_ep_links = {
        struct list_head *next = 0xffffffff81026995
        struct list_head *prev = 0
    }
    struct list_head f_tfile_llink = {
        struct list_head *next = 0
        struct list_head *prev = 0xffffffff817ae848
    }
    struct address_space *f_mapping = 0xffffffff00000064
}

For those of you who are observing, I picked a random symbol
in the kernel to prove this works ok, so dont treat that file structure
as having any meaning !

Post created by CRiSP v10.0.20a-b6134

llquantify

2011-12-17T02:39:00.001-08:00

Spent the week updating the dtrace source code to align with the
latest illumos sources. One of the new features in the latest dtrace
is the llquantify() function.

Rather than me trying to do justice to this function, its better to
let Bryan Cantrill give you the low-down, as in here:

http://dtrace.org/blogs/bmc/2011/02/08/llquantize/

Theres some kernel fixes/enhancements in here. (A fix for
ungarbage collected ecb's when a module is unloaded, but thats
currently disabled until I put in a fix for the timer callback;
module unloading is relatively rare, and untested on Linux/dtrace).

Heres the output of a run (inside a VirtualBox VM):


$ dtrace -n "tick-1ms{@ = llquantize(i++, 10, 0, 6, 20);}
	tick-1ms/i==1500/{exit(0);}"
dtrace: description 'tick-1ms' matched 2 probes
CPU     ID                    FUNCTION:NAME
  1 279854                        :tick-1ms


           value  ------------- Distribution ------------- count
             < 1 |                                         1
               1 |                                         1
               2 |                                         1
               3 |                                         1
               4 |                                         1
               5 |                                         1
               6 |                                         1
               7 |                                         1
               8 |                                         1
               9 |                                         1
              10 |                                         5
              15 |                                         5
              20 |                                         5
              25 |                                         5
              30 |                                         5
              35 |                                         5
              40 |                                         5
              45 |                                         5
              50 |                                         5
              55 |                                         5
              60 |                                         5
              65 |                                         5
              70 |                                         5
              75 |                                         5
              80 |                                         5
              85 |                                         5
              90 |                                         5
              95 |                                         5
             100 |@                                        50
             150 |@                                        50
             200 |@                                        50
             250 |@                                        50
             300 |@                                        50
             350 |@                                        50
             400 |@                                        50
             450 |@                                        50
             500 |@                                        50
             550 |@                                        50
             600 |@                                        50
             650 |@                                        50
             700 |@                                        50
             750 |@                                        50
             800 |@                                        50
             850 |@                                        50
             900 |@                                        50
             950 |@                                        50
            1000 |@@@@@@@@@@@@@                            500
            1500 |                                         0

Post created by CRiSP v10.0.20a-b6134

Ding dong! Who's there? Anybody? Someone say hello!

2011-12-11T13:41:00.001-08:00

Nigel has been up to his tricks again. No sooner do I give him
a new release, and after a 21h marathon, some dtrace problems surfaced.

I'm not sure if I have fixed or found the issue...but whilst trying to
reproduce the issue (and I am not happy having to wait 21h to get
a feel for the issue), I found a new bad scenario.

On a 3 CPU VM, if I run a simple syscall:::{exit(0);} type of probe,
repeatedly, then running *four* of these will deadlock the system.

After a lot of poking around, adding debug, and trying to understand it,
I think I located the source of the problem.

So, a process runs on cpu#0, and whilst holding on to the
locks, is suspended by the kernel. Next, another dtrace process
comes along and blocks waiting on the mutex held by cpu#0. Repeat
two more times.

Now, the mutex implementation is effectively a spinlock, and we dont
allow the first process, holding the locks to run. So we have deadlocks
and a hung system.

The cure appears to be calling schedule() in the middle of the mutex-wait
loop, avoiding cpu starvation.

This appears to work fine.

New release with this fix, and Nigel can spend another 21h finding
more bugs for me. :-)

Post created by CRiSP v10.0.20a-b6134

Couple of tools

2011-12-09T12:49:00.001-08:00

In the previous post, I talked about the difficulty of debugging
the cpu-stuck lock syndrome.

I thought it worth documenting a couple of trivial tools I wrote.

The first tool, is a simple "tail -f" tool. It seems that the GNU
"tail" tool doesnt work for character special device files. So:


$ tail -f /proc/dtrace/trace

doesnt track the new data in there. A char-special file doesnt have
a "size", so, when EOF is hit, you cannot necessarily do the standard
trick of seeking and rereading the new data.

Whilst debugging dtrace, its useful to keep an eye on /proc/dtrace/trace.
I had given up using kernel printk() messages for debugging, because
when faced with cpu lockups, you may not be able to see the messages
and earlier lockups had implied that the lockups were a by product
of multiple cpus causing printk() which in the later kernels, has
its own mutex.

So, tools/tails.pl does the magic of doing the tail. The algorithm
is very simple: keep reading lines, storing them in a hash table. If
we havent seen the line before, print it out. On EOF, sleep for a while
and keep rereading the file. Its cpu intensive (and potentially memory
intensive) but for the purposes, it fits the bill.

I also found it useful for tracking /var/log/messages, since in the event
of a stuck-cpu, you may not have a chance to see the file.

cpustuck.pl

The next tool - which is quite interesting, is trying to visually see
a stuck cpu. Almost, like a black hole, you cannot see it - its likely
stuck in a tight loop with interrupts disabled.

Heres how we do it: have a program which prints, to the console, once
a second, the cpu we are running on. Using the taskset utility, we can
ensure that this process *only runs on the nominated cpu*.

So, now the algorithm is: foreach cpu, spawn a child process, which can only run
on the specified cpu, and prints out the cpu it is on. By running these
processes in parallel, we will see an output sequence like (this is a 3-cpu
example):


0120120122100010002222220012012...

The order of printing is indeterminate. Under normal circumstances,
we expect all cpus to say something (in any order). If one or more
cpus lock up, then we will miss the notification, and the pattern breaks.
Eventually, if all cpus lock up, we will see no more output, and
usually no response to the keyboard, and pretty soon...the need to reset
the machine.

What this allowed was to detect *which* cpu was stuck, quite easily.
Unfortunately, that is all it does. We know a cpu is stuck but we
dont know what/where it is stuck.

Combine this with the "tail.pl /var/log/messages", and, if we are lucky,
when the kernel sisues the cpu stuck diagnostic, we can get a stack trace,
and get a better understanding of whats going on.

Its not sufficient - if we know the stack trace for a stuck cpu,
it may not be clear *why* it is stuck. In my case, it seemed to be
inside the code for kfree(), on a spinlock.

But to be stuck on a spinlock implies some other cpu is doing something,
which was not found to be the case.

In the end, the problem was really a deadlock which was not
easily understandable. One cpu is asking the other cpus to do something.
Whilst this is happening, the original cpu is being asked to do something.
But the first cpu is not listening (interrupts disabled).

The ultimate cure was to understand fully the two main areas where
dtrace blocks (mutexes and xcalls) and ensure they "knew" about
each other (mutexes will drain the xcall queue whilst waiting for
a mutex).

Post created by CRiSP v10.0.19a-b6127

Losing my marbles, err..mutexes.

2011-12-09T12:30:00.001-08:00

Interesting week on the dtrace front. At the beginning of the week,
dtrace was looking good. Surviving various torture tests.

But then Nigel had a go, and he reported a no-go. Slightly better
but not robust enough and could crash/hang the kernel within a few
minutes. The test was very simple:


$ dtrace -n fbt::[a-e]*:'{exit(0);}'

and

$ dtrace -ln syscall:::

running in parallel. The long teardown from the first dtrace
would allow the much shorter syscall::: list to interleave, and
sooner or later, lead to deadlock.

I modified the first dtrace to fbt::[a-m]*: to improve the chance
of the deadlock. (fbt::: is very draconian, enabling probes on all
functions, and makes ^C or other checks for responsiveness, a little
excessive. fbt::[a-m]*: was a middle ground - quick to fail.

In investigating this, I ended up writing a couple of very simple
but useful tools. The mode of failure was to cause "stuck CPU" messages
to display on the console. Linux has a periodic timer fire which
can be used to detect CPUs stuck in an infinite loop - a useful feature.
When the stuck cpu message fires, you should get a stack
trace in /var/log/messages (Fedora), or /var/log/kern.log (Ubuntu).

Unfortunately, once a CPU is stuck, chances are high that the system
is in an unrecoverable state - and attempting to look at the stacks
doesnt help. I occasionally could get the kernel logs.

Each time, I could see a suggestion that the cpu was stuck
in the kfree() function, freeing memory. As the dtrace session ends,
all the probes need to be unwound, and the memory freed. For fbt::[a-m]*:,
this is around 29,000 probes (and some multiple of this in memory allocations).

Freeing 29000 memory blocks should take well under a millisecond.
But it takes *seconds*. (See prior threads on slow teardowns of
fbt).

The reason it is so slow, is that dtrace needs to broadcast to the
other cpus, effectively saying "Hands off this memory block". This
involves a cpu cross-call to synchronise state. Unfortunately, this is
slow. It also does 3 of these per probe that is dismantled.

Previous attempts to optimise this failed. (Nigel had pointed out
this is significantly faster on real hardware vs a VM). I didnt
quite get to the bottom of why it failed...

So, we know we have a stuck cpu, something to do with freeing memory.
Very difficult to debug. I wanted to know what the other CPUs were doing.
If one cpu is waiting for something (a lock, semaphore, spinlock, whatever),
then the others must be causing the lock. The evidence showed they werent
really doing much.

During a teardown, the other cpus may continue to fire probes, so the
chances were that another cpu was causing a deadlock.

The big implication was that either my mutex implementation or my
xcall implementation was at fault. I spent a lot of time going through
both with a fine tooth comb, and trying various experiments.

It really didnt make sense. To cut a long story short, eventually,
after despairing I could ever find it, it started working! Having
made lots of little changes, eventually it survived over an hour, vs
the 1-3 minutes previously.

In the end, a couple of small changes were made (it wasnt obvious
which of the many changes were the cause of the fix). By suitable
diffing, and cutting back of the noise, I found that the xcall code
and mutex code needed to occasionally drain the pending xcall
buffers. If we run a cpu with interrupts disabled, and another cpu
is trying to call us, then we put a long delay in responding to the
function call. Worse, we can deadlock - the other cpu is waiting for us,
and we are waiting for that cpu. By suitable "draining" calls, the
problems disappeared.

So, hopefully it is hardened.

Lets see how Nigel copes with this, over the weekend.

Its worth noting that debugging this kind of code is very difficult.
I tried using the kernel debuggers, but faced a number of problems.
One is that you cannot interrupt the kernel to see whats going on if
the cpus have turned off interrupts. (I believe).

I'll document a couple of the tools I added to the war chest in a
follow up blog post.

Post created by CRiSP v10.0.19a-b6127

CRiSP 10.0.19

2011-12-04T07:08:00.001-08:00

I am going to release CRiSP 10.0.19, which has a subtle change
to the way configs are saved. It turns out that the gridlines/outline
mode cannot be persistently turned off. When you restart CRiSP, they
are back on.

This is because this is the first time (in a long while) that
the clean-install startup defaults changed, to enable these features.

When the config is saved, the internal defaults were defeating the
user selection.

So, in $HOME/.Crisp/crisp8.ini, the "display_mode" call is replaced
with two new lines: "set_display_mode" and "set_display_shift".

Most CRiSP primitives use a variety of flags to control behavior, rather
than having a single get/set(inq) function to control behavior. This
was for back in the 4MB-was-large days. So its time to liberate some
of the functions, where it makes sense.

What this means is that if you pick up 10.0.19 and dont like it,
and go back to an older release, those config lines will cause a
problem (a startup warning, possibly) until the older defaults are resaved.

I may upgrade crisp8.ini to crisp10.ini if this presents itself as a
problem.

Post created by CRiSP v10.0.19a-b6127

You locked me out! No I didnt.

2011-12-04T04:08:00.001-08:00

Just fixed a problem with the mutex implementation. It was trying
to support recursive mutexes, but dtrace doesnt like or expect that.

The effect was that "dtrace -l & dtrace -l &" would cause havoc
and assertion failures.

New code seems to fix that, and run much tighter.

Lets see if this cures problems.

Someone raised an issue today on USDT probes - that they are broken.
My response is "probably". I havent properly validated them in a while
in an attempt to fix all the other issues.

If nothing comes up, then I shall take a look at this next.

Post created by CRiSP v10.0.19a-b6127

Whats a nice byte doing in an instruction like this?

2011-12-03T02:39:00.001-08:00

Just spent a few days trying to debug a strange scenario in Fedora Core 16.

Trying to enable all probes would crash the kernel. After a binary
search, the function flush_old_exec was found to be the culprit.

Nothing special in that function makes it stand out, but putting
a fbt::flush_old_exec:return probe in would cause the next fork/exec
to kill the process. After trying every conceivable thing, nothing worked.

Obviously a bug in dtrace - could it be the trap handler? Interrupts?
Pre-emption? CPU rescheduling?

Whilst analysing and trying to resolve this, I did some interesting things.

The nice thing about localising the probe at error, was that I
could test (simply start a new process), and it wouldnt crash the kernel
but kill the new process. So, a very controlled environment for
making small changes and adding monitoring was possible.

Firstly, which probe was firing? Looking at /proc/dtrace/stats showed
that *no* probe was firing. I added some extra debug to the int1 and int3
handlers (single step and breakpoint), and this too, showed no
probe was firing.

Not possible ! Really not possible !

Ok, so next, had we actually armed the probe? Well, we can use
/proc/dtrace/fbt to examine probes, and we can tell if a probe is armed
(tell-tale sign is "cc" instruction as the opcode at the location). Yes,
we are arming the probe, but, no, it does not fire.

Next up is to disassemble the function itself. I have found it very
annoying with Linux that there is no /vmlinux binary on the system -
only the /vmlinuz (and /boot equivalents), which are not proper ELF
files, but bootable images. Something as simple as examining the instructions
and bytes at physical addresses is tricky. I had written a
"vmlinux" extractor, but it never worked reliably.

One trick I have to do this is the following:


$ sudo gdb /bin/ls /proc/kcore

We dont care about /bin/ls but use it so we can examine /proc/kcore, and
from this, we can access physical memory addresses (eg as reported
by kernel stack traces or the dtrace probes).

What I found was curious. The two RET instructions in the function
were slap in the middle of a CALL instruction.

This meant the instruction disassembler was wrong. Looking back
a few instructions to see why, we came across the infamous "UD2"
instruction. UD2 is a special instruction to generate an
undefined-opcode fault. In the old days, lots of opcodes could do this,
but Intel formally added this instruction so that compilers and
operating systems had a real instruction, that would never change
in future CPUs, for the purpose of generating an illegal instruction
trap.

The Linux kernel uses this in the BUG and BUG_ON macros. Since
these calls are called rarely, the kernel maps to an UD2 instruction
and the fault handler can gracefully report the fault and the location
of the error.

When the INSTR provider was implemented, I came across these
instructions and had put some special "jump-over-it" code in place
to handle this, but either I misread the assembler, or
the kernel changed. Whenever a UD2 instruction is met, the
disassembler would jump 10 bytes forward and continue from there.

This just so happened to be in the middle of a call instruction
which happened to have 0xC3 as part of the relative address field.
Dtrace then slapped a breakpoint on that 0xC3 instruction and
changed the call to something that was wrong.

As soon as we hit the call, all bets were off, and we were lucky
not to crash the kernel.

Interesting that this didnt show up in Ubuntu 11.x or FC15, despite
that code note really changing in a while, but it could be the
quality of the GCC compiler code changed to cause the opcode
to just match something plausible, whilst never tickling the bug
on different kernels.

So, one more bug down for now.

Post created by CRiSP v10.0.19a-b6122

Dtrace and Ftrace : cross-modification

2011-11-29T10:48:00.001-08:00

Brendan Gregg does a good write up of dtrace vs system tap, here:

http://dtrace.org/blogs/brendan/2011/10/15/using-systemtap/

I have been thinking about systemtap and ftrace, and stumbled
across a peculiarity in the performance game.

Solaris/dtrace has very little in the way of code when wondering
about dropping or removing probes. On x86, a probe translates into
a single byte breakpoint instruction. Dumping this on top of an
instruction is effectively atomic (forget about barriers and all
the other SMP complexities...for a moment).

But in diagnosing issues in linux/dtrace, I had to look at ftrace to
check my sanity.

On x86, you can safely write self-modifying code. For future portability,
Intel recommends instruction sequences to avoid problems with other CPUs,
and the term "cross-modifying code" is used, whereby you are modifying
instructions which might be sitting in the i-cache.

Now, in general, replacing an N-byte instruction with an M-byte, where
N != M is a problem, depending on if M > 1, and M > N. Atomically
modifying memory which might be executed by another cpu is "hard".

Linux 3.x and the ftrace code honor the Intel recommendation. They
*stop* all the other CPUs whilst making these probe changes and
use NMI interrupts to implement a hard locking region. Neat trick.

But very costly.

Solaris/dtrace doesnt. Neither does Linux/dtrace. We just "plop" our breakpoint
wherever we see fit and the CPU does the rest of the work.

This is great. But, Solaris/dtrace has a problem which they havent
noticed yet. In Linux/dtrace, I provide the instruction provider.
This provides additional ways to drop probes on "interesting instructions"
and there is a chance that the user could drop the same address
probe via FBT and INSTR.

So, when a breakpoint is hit, which one wins? On Solaris, I dont think
this can happen. It could in Linux, and at the moment, FBT will win
and INSTR wont get a chance to handle the probe.

Thats not so much a problem.

But consider this: how do you remove a probe? Well, you
just overwrite the instruction where you placed a breakpoint with
the original opcode byte.

There. Done. Nice. Neat.

Hm...not so...

Solaris/FBT does not have a notion of a probe being enabled or not.
It does...but it uses the breakpoint byte to indicate that the probe is
set or not. In fact, Solaris/FBT doesnt really care.

So consider this: when disabling an FBT probe by overwriting the instruction,
and another CPU, who has yet to see the byte modify, executes that
instruction, may in fact, execute the breakpoint trap, even tho the probe
is undone. So, now another CPU fires a FBT probe which was disabled.
And Solaris/FBT lets it happen. It blindly fires the probe.

But, at this time, *nobody is listening*. This is fine - but a probe
is potentially firing when it should not do.

The reason is, that Solaris doesnt flush the other CPUs i-cache.

I noticed this on Linux, that probes were firing, even after dtrace had
terminated because I was handling the enabled/disabled state. This
caused a problem. If FBT knows the probe cannot fire, then it wont
intercept it. And if this happens, then we have a breakpoint
trap and the rest of dtrace wont know how to handle the breakpoint - we
wont know what the original byte of the instruction was.

I had to disable this feature and allow FBT to process probe traps
even if the probe points had been disabled.

Which all comes down to the fact that cross-modifying code is
extremely intrusive, but you can get away with it, until one day,
you might not. ("One day" might mean on a different CPU architecture
or some future Intel chips).

And finally: if Solaris had done the "right thing" it might be very
slow at placing lots of traps or removing them. And this might account
for ftrace losing some aspect of performance compared to dtrace.

BTW the current latest release of dtrace is proving remarkably resilient.
I am up to 5.3 billion probes running the torture tests, on real hardware,
and no problems so far.

Post created by CRiSP v10.0.18a-b6115

I am going nuts.

2011-11-28T14:56:00.001-08:00

So, Nigel got me to check dtrace with real hardware. And my heart stopped.
It ran, and then hung the machine. I narrowed down to an "fbt::form*:" (46
probes) and it kept hanging.

Nothing I could do could make it work. (Relaxing locks, removing
all the actual probe capture code). I assumed the worst - a CPU
L1/L2 caching issue against the SMP cores.

So, I tried on my VirtualBox VMs, and it was the same! Now, this
worked perfectly yesterday, and I hadnt changed anything. Amazingly,
"fbt:::" worked well, but a narrow FBT probe did not.

After narrowing it down further, it transpires that some of the calls
to printk() (which now map to the internal dtrace_printf, rather than
the real kernel printk) were causing some form of recursion fault.
After modifying the dtrace_printf() and printk() code to avoid this,
it worked as I had expected before. Nicely. On real hardware.

Now, something else is strange. I keep talking about rapid-fbt-teardowns
being slow. I had done a lot of work to optimise this, and was proud
of my ~10s of execution, down from more than 30-40s. On real hardware,
this was coming in at sub-second. Now, on my VirtualBox, it was
subsecond too! I dont know if the act of rebooting my laptop and
starting afresh had fixed the issue, or some other nastiness (like
the recursion above) had caused a performance issue to disappear.

I checked the timer (tick-1ms) again - and thats still bad,
at about 350 x 1ms ticks per real second.

(I wonder if my VirtualBox slowdowns could be triggered by a paused VM).

Post created by CRiSP v10.0.18a-b6115

Slaphead time...

2011-11-28T09:36:00.001-08:00

Whilst diagnosing something fishy in dtrace the other week
(why xcalls are so slow), I was going to write that its obvious:
when running in a VM, things are slower.

I got distracted, and have been chasing up issues and breakages in dtrace.

Nigel - such a great person for feeding back breakage and issues,
was asking me why I was spending so much time on the teardown code.
Its rare that people do "dtrace -n fbt:::" and they get what they deserve.
I said, well, it has to be safe.

He then said, well, the figures in my prior blog didnt add up: I was
quoting a great achievement of ~10s to teardown, and he was seeing
sub-second teardowns. *On Real Hardware*.

Duh!

So, I just checked. My 10s teardown is about 0.5s on a Pentium Core 2.33GHz
machine:


218.620320647 #0 teardown start 1322505021.895618798 xcalls=90677 probes=423796
218.680320738 #0 teardown done 0.60000091 xcalls=181282 probes=291

So, double Duh! I also checked the tick-1 test:


$ dtrace -n '
	int cnt_1ms, cnt_1s;
	tick-1ms {
	        cnt_1ms++;
	        printf("%d %d.%09d", cnt_1ms, timestamp / 1000000000, 
			timestamp % (1000000000));
	        }
	tick-1s { cnt_1s++;
	        printf("tick-1ms=%d tick-1s=%d", cnt_1ms, cnt_1s);
		cnt_1ms = 0;
	        }
	tick-5s {
	        printf("the end: got %d + %d\n", cnt_1ms, cnt_1s);
	        exit(0);
	        }
'

And I get around 980 x 1ms ticks per second, vs around 250 x 1ms on a
VirtualBox VM (running on an i7 2630 chip).

So, there we have it. Proof that a VM is slower -- very significantly
in some areas, and one must be very careful to attribute performance
in a VM to anything like real world. (Its not really surprising -
playing with timers or doing cross-cpu interrupts, has to be mediated
by the host VM). These dtrace tests are extreme and so amplify the weakness
of a guest VM.

So, I have partially wasted my time in doing these optimisations, but
actually, they are useful, allowing me to refine the port to Linux, but
also to look for and find, potential issues which might show up after
a much longer period of soak testing on real hardware.

Now...off to fix the next bug....

Post created by CRiSP v10.0.18a-b6115

DTrace and the quest for resilience.

2011-11-27T09:55:00.001-08:00

So, third time lucky at resolving the fast-teardown issue.
The fast-teardown was proving too erratic.

This release re-enables the standard teardown. The performance difference
here of fast teardown vs classic is about 40+s to terminate an fbt:::
vs 3-4s.

I've put in a different optimisation, which not as good as the
original fast teardown, is a decent optimisation (around ~10s).

The new optimisation realises that during teardown, not only is
the current cpu invoking probes (eg dtrace_xcall invokes the functions
to send an IPI interrupt to the other cpus, and the probes for our
current cpu are totally pointless), but also the others are
just passing the time, doing "stuff" and invoking probes. So, we try
to "slow down" the other cpus - as soon as they try to probe, we
put them in a small poll loop, checking for xcall calls.

I put some stats into /proc/dtrace/trace to show the tail of the
teardown. Heres an example. (4-cpu VM):


46.251921756 #3 teardown start 1322415220.918787912 xcalls=35 probes=2964975
51.106543255 #3 [3] x_call: re-entrant call in progress.
56.645252318 #3 teardown done 10.393330562 xcalls=108922 probes=1161780

The teardown took 10.3 seconds, and during this time, 1,161,780 probes
fired. We did 108,922 xcalls. (Previously we did a handful only - the
xcalls are very expensive).

Post created by CRiSP v10.0.18a-b6115

gcc 4.6.1

2011-11-26T10:12:00.001-08:00

The world of compilers should be boring. But I am impressed by
GCC 4.6.1.

Having upgraded my Ubuntu system, I now get the pleasure of the
latest compiler.

After 25+ years of CRiSP development, the code is pretty stable,
and most bad things have been ironed out of the code base. Having
been ported to just about every operating system out there
(from Cray, to a 512K RAM 80186 MSDOS handheld), and used just
about every compiler ever, its refreshing when the compiler takes
warning-free code, and starts telling you about variables which
are set and never used.

Previously, the compiler would warn on a variable defined, but
unused, but wouldn't notice something like:


	void func(void)
	{	int	n;

		n = some_other_func();
	}

gcc 4.6 does. So, you get to look to see why you are assigning a
result but never using it, and, in some instances, the call to the
function might hint the call is not needed, especially if that
function is a "pure" function.

Nice.

My only complaint now is that its a bit noisier in a couple of other
benign warnings (and hence, its more difficult to see the errors
of interest).

Post created by CRiSP v10.0.18a-b6115

New dtrace release

2011-11-25T15:29:00.001-08:00

After the release last weekend, more work was done to chase down
reliability issues. They never seem to disappear. Lets hope this is
better than the last "good one".

The Fedora Core 15 kernel has some "different" stuff in it compared
to Ubuntu - I tracked down a few unique instructions at the probe
entry points which werent emulated properly.

I also fixed some other bugs in the instruction emulator.

Next, the fast-teardown mode wasnt resilient enough and had to be
rewritten. Without this, Ctrl-C a fbt::: probe could take 20+ seconds
due to the frantic xcall conversations as each probe is removed one by one.
Ubuntu and Fedora would complain about a stuck CPU when this happens,
which isnt very social.

The new fast-teardown removes all dtrace_sync() calls, bar a few.
(I would like to know how Apple does it; I know how Solaris does it; I
dont know if FreeBSD is "as good as" Apple, or very poor). What is very
interesting in this area is that I dont believe the Solaris mechanism
can work on Linux, since Linux can have interrupt-disabled spinlocks which
can prevent cross-cpu interrupts from happening and causing deadlock.
My solution was to keep the lockless solution from before, but
avoid the 2x calls to dtrace_sync per probe teardown, but "using a better
algorithm". For simple one/two probes, it doesnt matter, but when you
have 40,000+ probes in flight it makes a big difference.

Now the next issue is the tick/profile provider. I found today
that the "profile" provider isnt implemented (it generates a TODO
warnings). On re-reading the Solaris tick/profile provider pages, I
found they are "wrong". The documentation refers to the fact that
you can use, e.g. "tick-1us" to have microsecond level granularity probes,
but they are not supported. Dont know why (maybe my source code is
out of date, or they felt it too worrisome to support them).

My favorite provider at present is "tick-1ms" - a one millisecond tick.
I knew dtrace/linux could "drop" probes when under pressure, but I havent
had time to investigate why. A simple test:


dtrace -n '       int cnt_1ms, cnt_1s;
        tick-1ms {
                cnt_1ms++;
                printf("%d %d.%09d", cnt_1ms, timestamp / 1000000000, timestamp % (1000000000));
                }
        tick-1s { cnt_1s++;
                printf("tick-1ms=%d tick-1s=%d", cnt_1ms, cnt_1s);
                }
        tick-5s {
                printf("the end: got %d + %d\n", cnt_1ms, cnt_1s);
                exit(0);
                }
'

Lets you quickly see if there are 1000 tick-1ms probes in a second.

There arent.

Linux is achieving about 750/sec, and MacOS achieve around 997/second.

I suspect my attempts to get it to "work" have left a gap in that the
timer is not a cyclic timer, but a refiring timer, so the latency between
handling the end of one tick and repriming the timer, is causing is to expose
a window. Thats probably a part of the explanation; there may be more.
On an idle system, losing 25% of the ticks seems a bit excessive.
(Dtrace/Linux can achieve in excess of 1-2m probes/sec, so, 1000 measily
ticks shouldnt be too bad).

I need to experiment further. Some things that could be affecting this include:
(a) bad (my) code, (b) virtualisation, (c) high latency kernel scheduling.

I hope it is (a).

Post created by CRiSP v10.0.17a-b6112

1 in a million

2011-11-22T14:52:00.001-08:00

So, Nigel had reported on the sporadic crashes. Had me very
stumped - running the test suite and being really nasty to the kernel
caused everything to pass. However, I did get a "simple" test to try:


$ dtrace -n fbt:::entry'{cnt++;}'

Some minutes after leaving this running would cause a kernel
assertion about interrupts being disabled when they shouldnt be.

This was a real needle in a haystack - a problem, which occurs
after millions of probes is almost impossible to find. Was it one
specific probe, or maybe single-step, or a race condition in
terminating interrupt routines.

How to find it?

Well, I started by adding /proc/dtrace/fbt - which gives a birds eye
view of every FBT probe, along with state, and how many times it had
been hit. I augmented this with the instruction which was probed.

Running a full fbt::: would cause a large fraction of all kernel
functions to be hit, but, equally, large numbers of functions that are
never called (eg for device drivers which are not active).

In a sense, this device gives a coverage view of FBT traps.

By casting out the known "good" probes, I was left with potentially
hundreds of distinct instructions/probes to wade through.

I didnt get far, other than to look for patterns. If we have a 1:1,000,000
failure, then something has to be happening infrequently. Using the
probe counter for each probe, we get some idea of the rarely called functions.

Whatever was causing the issue wasnt so much a single function being called
and blowing up the kernel, but a small piece of "damage" because the
trap handler didnt do the right thing.

The kernel kept saying the same thing: interrupts were unexpectedly disabled,
but knowing which trap was called just prior to this event was nearly
impossible to determine.

Finally, I started the "binary search" mode of attack: Lets ignore
all instructions which start 0xFn, then 0xEn, ... At some point, around about
0x9n, the problem seemed to disappear. (Absence of evidence isnt evidence of
absence!). Disabling all 0x9n instructions would allow dtrace to run
for hours without issue. Re-enabling would cause a warning within minutes.

Ok, so what are the 0x9n family of instructions? Well, 0x90 is a NOP - quite
common in the kernel, and nothing of interest. Heres the full list:


       90                      nop
       91                      xchg   %eax,%ecx
       92                      xchg   %eax,%edx
       93                      xchg   %eax,%ebx
       94                      xchg   %eax,%esp
       95                      xchg   %eax,%ebp
       96                      xchg   %eax,%esi
       97                      xchg   %eax,%edi
       98                      cwtl
       99                      cltd
       9a                      (bad)
       9b                      fwait
       9c                      pushfq
       9d                      popfq
       9e                      sahf
       9f                      lahf

The main instruction of interest above is pushfq. So, exactly how many probes
have PUSHFQ in the first instruction of the function? Well, exactly two, on my
kernel:


# count patchpoint opcode inslen modrm name
...
21603 0000 ffffffff81032704 9c 1 -1 kernel:end_pv_irq_ops_restore_fl:entry 9c
...
24295 0010 ffffffff81539c00 9c 1 -1 kernel:native_load_gs_index:entry 9c

Now, env_pv_irq_ops_restore_fl hasnt been called (column 2), but
native_load_gs_index, was called 16 times. So, this isnt on every
syscall or interrupt, but its a rare occurrence. And that is what
we are after.

So, off to examine the code, and I found a bug. PUSHFQ was deliberately
disabling interrupts (because of a bug), and PUSHFQ doesnt touch the
interrupt flag. So, bingo! We could return back to the kernel with interrupts
disabled, and, luckily, the sporadic consistency checks would tell
us that interrupts were disabled when they shouldnt be.

When writing code in an SMP kernel, having interrupts disabled and sleeping
waiting for an event, can lead to deadlock. Thats why the checks are there.
And they helped, very nicely, to say "something is wrong" although, not
exactly where.

So far, dtrace is holding up well.

Lets see if Nigel is happy now.

Post created by CRiSP v10.0.17a-b6112

Dtrace bugs...

2011-11-20T14:21:00.001-08:00

Nigel has been letting me know things are not 100% yet. He has a very
rare scenario of a crash, and I have some issues with launching
firefox whilst tracing all system calls.

Looks like at least one isnt totally correct for some reason.

May take a while to debug these scenarios (syscall tracing should be
deterministically easy), but 1:1,000,000,000 is more tricky to
diagnose. Maybe I can add enforced long delays to force interrupt
traffic to jam up across the cpus.

Post created by CRiSP v10.0.17a-b6112

NMI revisited

2011-11-20T14:18:00.001-08:00

After researching and reminding myself how it works, we can have
probe points from an NMI, but first, we need to fix the interrupt
handlers.

An NMI interrupt can interrupt a normal interrupt routine. A normal
interrupt cannot interrupt the NMI. *But* an NMI can take a trap, e.g.
a breakpoint trap.

So, now the fun starts. When an interrupt terminates, the handler
executes an IRET instruction. An IRET is very similar to a POPF/RET
instruction sequence except for one very subtle point.

The subtle point is that the IRET will dismiss an NMI. If we
execute an IRET from a breakpoint trap which trapped inside an NMI interrupt,
then chances are that the NMI will be immediately reasserted - from
inside the NMI interrupt handler.

This blows up and the CPU will hit a double or triple fault and reboot.

So, to restate, no interrupt can execute an IRET if we are nested inside
an NMI. Therefore we need to keep some state.

Heres the hint at what can happen:

https://lkml.org/lkml/2010/7/14/417

and

http://linux.derkeiler.com/Mailing-Lists/Kernel/2010-07/msg05459.html

which details the tricks the kernel is doing to handle the nested
interrupt structure.

Now, I need to figure out how to do the same thing without damaging
the kernel. (I have some prototype code but need to fix one issue).

Post created by CRiSP v10.0.17a-b6112

NMI #2

2011-11-18T14:58:00.001-08:00

Just put out a new release which hacks around the NMI issue - whilst
dtrace is loaded, we do not propagate the NMI to the kernel. This
certainly seems to fix the dtrace-on-real-hardware issue.

At a cost/loss of being able to have NMIs.

Next up is to contemplate only disabling NMI when no probes are active,
but better is to figure out how to avoid a double-trap if we hit an NMI
probe. I dont know if thats possible, by definition of an NMI.

(Solaris gets away with it, because I suspect the NMI code is such that
nothing uses it and/or dtrace wont allow probes to those functions?)

Post created by CRiSP v10.0.17a-b6103

Dtrace and the NMI Interrupt

2011-11-18T14:40:00.001-08:00

Nigel has helped greatly in moving us forward on Dtrace. The latest
release works well inside a VM, but alas, might not work on real hardware.

I ran some tests on Ubuntu 11.04 on real hardware and dtrace was
rock solid (well, it survived 500m+ probes and running the test
suite twice over).

But, if the real hardware is generating NMI interrupts then we are toast.
Ubuntu doesnt do this by default. Maybe Fedora does, or its a function
of the hardware and cpu.

What I found is that if I loaded the oprofile package (which uses NMI
interrupts to feed the profiler), then the host will reboot if dtrace
is loaded or if its invoked.

The reason is more than likely that within the NMI handler of the kernel,
if we place a dtrace probe, then we will trigger a breakpoint trap
from inside the NMI handler. I dont believe this is valid or meaningful
(nothing should interrupt an NMI - it should only be used for small
lightweight and contextless operations, such as watchdogs).

So, we have a problem because we dont know the call graph of an NMI
interrupt, so we dont know what is safe to probe (even if we did know,
chances are high that common/useful probably routines would have to be
excluded).

I will experiment with turning off the NMI whilst dtrace is loaded.
Thats a very unfair thing to do (disabling oprofile, or other real
hardware events which need NMI), but at least we would be safe.

I am going to research what Solaris does for NMI ints. Maybe
that will educate me to the problem.

Post created by CRiSP v10.0.17a-b6103

Dtrace .. new release

2011-11-17T14:31:00.001-08:00

I just put out a new release. Hopefully this fixes a number
of stability issues and some silly bugs. I have rewritten the mutex
code to decouple from the kernel, and avoid reentrancy issues.

Just as I was about to release this a few days back I found a regression
where on repeated driver reloads, the kernel would crash or complain
of interrupts being disabled when they shouldnt.

I spent ages trying to drill down to where I had screwed up, and
in the end, it was a really stupid typo (sizeof(mp) vs sizeo(*mp)).

Glad to fix that and get back to a degree of sanity.

So this release has been tested exhaustively on Fedora Core 15 and
Ubuntu 11.10 (Linux kernel 3.0). I may have broken the build on
earlier kernels, and am looking to try and test on the earlier releases.

Please give it a try.

As an aside, I did get an email from someone trying out Dtrace on an
Oracle Linux host, and getting some strange complaints when /usr/bin/dtrace
didnt like the command line. /usr/bin/dtrace is *Oracle*s dtrace, not mine,
and hopefully the person is in a better position now running a working
dtrace on the system.

Lets see how much damage people can do to this. Many thanks to Nigel Smith
who kept harping on at me for "this doesnt work" which lead me to deep dive
a number of corner cases.

I have temporarily disabled some aspects of pid tracing/shadowing
and will need to fix that before evaluating the whole pid tracing space.

Post created by CRiSP v10.0.17a-b6103

Scrollbars: Time to banish them

2011-11-14T13:14:00.001-08:00

Theres two implementations of scrollbars which need to be
fixed.

First, Ubuntu scrollbars are annoying. Very annoying. The Ubuntu
scrollbar is invible until you move the mouse close to where
the scrollbar is and then the partial scrollbar appears. Why?
Its unobvious and annoying having to have your eyes track for the
existence of the scrollbar before you can scroll. 30+ years of GUI
development chucked down the drain.

Second, an iPod scrollbar. When watching a movie, many shows I record
from TV have adverts. They are predictable. If I am watching a 2hr or
more show, and an advert appears, then I use my finger to scroll
past them. But on a long show, a 2-5min interlude is a tiny
fraction of the scroller, and its nearly impossible to do this accurately,
especially as the ipod/iphone scrollbar is not analogue, but digital
in nature, leveraging 10s-1m+ scrollable fragments. The ipod has a way
to fine-scroll, but for a long film, its very difficult to scroll
accurately whilst keeping an eye out for where the advert break ends.

Whats really needed for the ipod is a scrollbar which is wider
than the screen, so you can quickly "flick thru" without worrying
that the longer the show, the more inaccurate the scroller is.

(Another bad design: why cant you see the title of what you are watching
on the scroll area? One has to stop watching the show to see what it
is you are watching.)

The scroller size on an ipad is not an issue, because there are so many
pixels to play with.

If you think scrollbars are easy, then think again. If you are
scrolling through a 1-million line file, there are not enough pixels to
scroll to an arbitrary line in the file. Even CRiSP uses a
fractional position, which for larger files can mean a single pixel
move of the scrollbar could map to 1000 lines in a file on a 1000-pixel
high scrollbar.

Post created by CRiSP v10.0.17a-b6103

In..Out..In..Out..Shake it all about !

2011-11-12T15:23:00.001-08:00

In the beginning was the mutex. And lo! This was mapped to a Linux mutex.
But this caused problems, because a mutex cannot be used inside an interrupt
routine.

On the second day, this was mapped to a semaphore. Semaphores are good.
They can be used in an interrupt routine.

On the third day, the semaphores were replaced with custom mutexes
(effectively spinlocks). Because a semaphore could suspend the calling
process inside a nested interrupt.

On the fourth day, the custom mutexes were replaced by semaphores,
because a timer probe would invoke calls to spinlocks and preempt
disables, and lead to recursive probe faults.

On the fifth day, the semaphores were replaced with different custom
mutexes. Ones which supported nested operation, and avoided depending on
Linux functions.

Get the picture? Its complicated.

Why is it so complicated? Because Solaris interrupt management
(via splx()) doesnt map to a the cli/sti mode of a processor. Solaris'
interrupt mechanism has existed for nearly two decades, based on
a processor model defined for the PDP-11. Linux's model is sophisticated,
and different.

One thing I realised this week .. why it took me so long, I dont know,
is that when you take a breakpoint trap, interrupts are left enabled.
This means, during an FBT probe, the timer can fire and you have a nested
interrupt.

This week has seen me try to solve Nigels Fedora Core issues where,
under load, the system would panic and reboot. The root cause here is nested
interrupts, and the dtrace module not segregating itself strongly enough
from the real kernel, allowing nested operation and deadlocks to arise.

I have to be very careful to get the key execution paths working in my
head (an fbt/breakpoint interrupt, a timer/tick interrupt - both standalone
and on top of an fbt/breakpoint interrupt, and the xcall/deadlock issue).

I also believe I have caught another implementation issue. Interestingly
I believe Linux ftrace mechanism suffers the same issue. Namely,
when single stepping, one has to be careful of 64-bit instructions
which use %RIP relative addressing modes. Both dtrace and ftrace almost
do the right thing, but can fail if dtrace is more than 4GB away from
where the kernel is loaded. (I think this might explain some erraticness
on large RAM machines).

I am not sure there is a cure for this (well, not a quick/easy one), and
I may have to disable those offending probes (typically only a handful on
a normal kernel - not a great loss).

Anyway, let me continue experimenting with mutexes and see how close I
can get. (My current experiment is real good, except for problems when
kzalloc is called with a mutex...lets see if I can fix that).

Post created by CRiSP v10.0.17a-b6103

Dtrace fixed (hopefully)

2011-11-07T15:30:00.001-08:00

I just put out a new release which fixes the terrors of the
last release. Hopefully this is more stable.

I found a bug in strace which caused repeated SIGSEGVs in one
of the tests (strace fails to trace a process it is launching
in about 1:100 test cases), even without dtrace active at the time.

I havent integrated in the fast-teardown/xcall optimisation yet,
as I need to tidy that up. Hopefully in the next release.

Post created by CRiSP v10.0.17a-b6103

Dtrace .. what a crock

2011-11-07T14:36:00.001-08:00

I put out a new release over the weekend, and all I can say is apologies.
It appears to be a very bad release. Initial testing was positive,
but Nigel pointed out some glaring errors, and on investigation
some of my changes were bad regressions.

I think I have the issues resolved/understood, and hope to put
out a new release today to fix this mess.

Post created by CRiSP v10.0.17a-b6103

Dtrace TCP Provider

2011-11-06T05:01:00.001-08:00

Now that some of the hard work of getting 3.0 kernels working is out
of the way, I am now looking to add the TCP provider.

Heres the first very simple cut:


$ dtrace -l -P tcp
   ID   PROVIDER            MODULE                          FUNCTION NAME         48        tcp                                                     state-change
$ dtrace -P tcp
dtrace: description 'tcp' matched 1 probe

CPU     ID                    FUNCTION:NAME
  0     48                    :state-change
  0     48                    :state-change
  0     48                    :state-change
  0     48                    :state-change
...

It doesnt provide the arg0/arg1 values in the probe callback, but will
see what I can do.

Nigel just reported that the new release is better (thanks for the quick
feedback Nigel), but that this is showing a problem:


$ dtrace -n 'fbt:kernel:: BEGIN {exit(0);}'

On my kernel, it slowed down enormously, but after 60s of no RCU response,
the kernel just hangs. So, off to fix that.

Post created by CRiSP v10.0.17a-b6103

How fast is fast?

2011-11-05T16:46:00.001-07:00

In deeper diving the dtrace lockup on 3.x kernels, I have
been revisiting the xcall code.

Heres a test for you to try (on FreeBSD, MacOS, Solaris and Linux):


$ dtrace -n fbt:::

This will trace all the FBT probes (on my Linux VM, thats about 48000
probes). "Time" how quick it is to start scrolling the output. (About 1-2s?)

Now ^C (twice, you need to do this twice for some reason in dtrace).

How long til you get your shell prompt back? (On my linux system,
its down to 1-2s vs maybe 3-4s on a dual core MacOS box).

Why is it *slower* to exit than it is to invoke?

The answer is: IPI or interprocessor interrupts. Now, this may
be fast on Solaris - its engineered nicely. On Mac and Linux at least,
its not. Its really difficult to work out "why".

When you ^C dtrace, it has to tear down all the probes. In theory
this is easy, and faster than the initial construction. But the
Solaris/Dtrace code has a nasty performance issue. For every probe,
three dtrace_sync() functions are invoked, and this involves
communication with the N-1 other CPUs to process an IPI interrupt.

This is what I emulate on Linux. But its slow. My 48000 probes
involve nearly 200k IPI interrupts to the N-1 processors. (I am
testing on a 4-cpu VM). And the IPI is either delivered "slowly" or
"received slowly" on the target CPUs.

What is worse, far far worse is the Linux 3.0.4 kernel I am
using in Ubuntu 11.10 (I compiled my own; the default distro is
3.0.12). If the tear down takes too long, the kernel may notice
a "hung" cpu, and after a minute or two, will hang, hard, the kernel
due to the lack of responsiveness. (I will need to see
if I can find out how it knows the CPU is not-idle, and maybe fool it).

I really dislike this 3.0 kernel - its a very harsh environment
for a buggy driver to live in, and dtrace has to work even harder
to avoid being caught in the searchlight of the kernel.

I have a hack/optimisation for this problem, which is proving
rewarding (if the "other" cpu is not sitting inside a dtrace probe
handler, then we have nothing to do, so we can skip the IPI interrupt.
But its not bullet-proof in the few lines of code addition).

How does Solaris handle this? Well, on Solaris, direct interrupt
disabling does not happen. Instead, a software processor level flag
is set, and the interrupt handler can allow interrupts, even if
logically, the code in question, does not want to be interrupted.
I believe by making direct dtrace checks, that IPIs across cpus
can happen even if the other cpu is in a critical section. I wish
I could prove my understanding of the code (but that would be a distraction).

Hm. Just took a look at Oracles version:


void dtrace_xcall(processorid_t cpu, dtrace_xcall_t func, void *arg)
{
        if (cpu == DTRACE_CPUALL) {
               smp_call_function(func, arg, 1);
        } else
               smp_call_function_single(cpu, func, arg, 1);
}

All I can say is good luck to them if thats what they think is sufficient
to do the job. Thats pretty much the code I implemented originally, and
it doesnt work.

Oh well.

Post created by CRiSP v10.0.17a-b6103

Dtrace progress

2011-11-05T02:47:00.001-07:00

I've spent the last week or so looking at why Dtrace on the 3.x
kernel is misbehaving and found some interesting things on the journey.

Firstly, printk() seems to be broken. In the 3.x kernel, they
appear to have added a recursion detection and stronger locking
semantics, which means attempts to call printk() from an interrupt
(or some other strong locking mode), will hang the kernel.

That has made debugging the other problems very difficult.
So be it, I have removed or disabled most of the printk() console
output.

I have an internal function - dtrace_printf() which does what
printk() does, but writes to an internal circular buffer, which is
safe, but isnt much help if the kernel locks up.

I have decided to move totally away from the kernel spin locks
and mutex/semaphore support, and use my own mutex implementation.
This avoids problems when the kernel mutexes can allow preemption
and other re-entrant problems, probably leading to some of the lock up.

I even went the whole hog and added the kernel debuggers to try and
debug the problem (kdebug/kgdb). This was totally unuseful for two
reasons. One, you cannot set breakpoints in the kernel (despite
trying). I had to turn off the kernel RODATA config option
since this prevents some parts of the kernel being writable,
but I still got errors. I could never get the debugger to wake
up on an RCU lockup or allow interactive "break-in" to the locked
up kernel.

The kernel rarely panics - it just locks up. Very frustrating.

Having fixed various things, it appears dtrace works much better.
The "dtrace -n fbt:::" works very well, EXCEPT ctrl-c can hang the kernel.

What is interesting is that during ctrl-c of dtrace, the amount
of work to teardown the probes is huge - specifically, the number of
xcalls called on teardown is about 3x the number of probes actually
played. So, down an fbt::: probe, which is placing around 40,000
probes, means on the ^C, the system is sluggish for a number of seconds as
tens/hundreds of thousands of xcalls are invoked. I think this is
problem which needs to be addressed in the real dtrace.

The problem is that as each probe is torn down, a number of dtrace_sync()
calls are invoked, and each one is talking to all the other CPUs
to ensure synchronisation. For reasons I cannot tell, this
is very expensive - presumably the other CPUs may be in a disabled
interrupt state, so we have to wait for that
cpu to come out of the interrupt region, or leverage the NMI
interrupt to break the deadlock.

I'm still trying to understand how xcall works -- if we ask
another cpu to take an IPI interrupt and it is stuck in a long
spinlock, then the xcall may take a while or forever to be invoked.
I dont understand how Solaris breaks this deadlock, but it does
appear solaris tries hard to keep interrupts enabled at all times,
which is different from Linux. I may have that misunderstood in Solaris.

MacOS does something different/similar in that on a xcall, the
invoking CPU keeps an eye out for recursive TLB shootdowns.

I hope to make a new release of dtrace in next few days if
I feel happy I havent made things worse.

I really dont like the Ctrl-C/teardown performance - it can
lead to the kernel complaining about stuck CPUs.

Post created by CRiSP v10.0.17a-b6103

Dtrace and printk()

2011-10-30T15:25:00.001-07:00

Been debugging lockups in 3.0 kernels. Very difficult to debug, since
all attempts to diagnose what was causing it were met with kernel
lockups.

Sometimes a trace like:


$ dtrace -n fbt::[a-e]*:

would work, and sometimes not. Lots of variations and thought processes
were applied, and nothing worked.

Then, after a little rest, I went back to basics. Lets assume one function
blocks us, so we try the binary search to see which fbt function it is.

Turns out that the new kernel has modified printk() - the kernel
printing function in some way. (I think its to do with recursive prints,
but not concluded this yet).

What appears to be happening is if printk() is called at the wrong
time, the kernel will lock up, waiting on a semaphore, to detect if
the console is free for printing.

printk() is not normally called much during dtrace, but there
seem to be enough places. If I map printk() to a do-nothing function,
then sanity appears to be restored and I can run against fbt:::.

So I need to either avoid printk() in dtrace, or, be judicious where
its used. (Dtrace already has an internal dtrace_printf function to write
to an internal circular buffer, but thats not visible if the kernel
crashes; I may need to fix that).

So, if you are having trouble on Ubuntu 11.04 or 11.10, or other
equivalent, using Linux 3.0.x, then stay tuned.

Thanks Nigel Smith, for pushing me to go hunt this down.

Post created by CRiSP v10.0.17a-b6103

Dtrace .. does it work. Yes. No. Yes. No. What?!

2011-10-29T01:23:00.001-07:00

Got a strange one here. Nigel Smith reported issues running dtrace
on real hardware (FC15). I could reproduce the issue on
Ubuntu 11.10 (Linux 3.0.0). A simply


$ dtrace -n vminfo:::'{printf("%s", execname);}'

would panic or hang the kernel - not straightaway, but within say 5mins,
especially if doing a:


$ while true
> do
> date
> done

in another window.

I've been staring at the dtrace code and trying various things to
see what causes it. Its an annoying panic because I lose control of the
kernel and no way of figuring out what happened immediately leading
up the issue. The stack trace on the panic doesnt help
(I am seeing the same panic in the e1000 driver cleanup code,
but no references to dtrace causing this).

I suspect dtrace is taking an interrupt, maybe not restoring a
register and sometimes, that register happens to be important.

Especially strange, as, running on Ubuntu 11.04 (2.6.38 kernel),
it works fine. I can really torture the system and it stays up.

I need to dive more into the entry64.S code to examine what changes
happened around the way an interrupt is handled. If I am lucky I may
be able to localise this to a register issue (%GS is a high probability).

Linux is really missing a kernel debugger. Theres kgdb and remote
debugging available, but this is really painful, when you suddenly
need to have to compile a new kernel, waste more than 1GB of disk
because of the symbol table, and then try and get it all "working".

What is needed is a better way to take control on a panic, and
poke around, similar to kadb for older Sun machines.

I might have to start writing a crude debugger to help with
these annoying "you died but I am not going to tell you why" issues.

Post created by CRiSP v10.0.17a-b6103

Dtrace release 20111026

2011-10-26T14:53:00.001-07:00

This release is an interim release. It fixes the issue I wrote about
earlier, but likely will not compile on kernels earlier than 2.6.39.

It is the first working example of the vminfo provider. Heres a small
sample of the vminfo probes:


   48     vminfo            pgmajfault
   49     vminfo            unevictable_mlockfreed
   50     vminfo            pgfree
   51     vminfo            unevictable_mlockfreed
   52     vminfo            compactsuccess
   53     vminfo            compactfail
   54     vminfo            pgdeactivate
   55     vminfo            pgrotated
   56     vminfo            pgactivate
   57     vminfo            kswapd_low_wmark_hit_quickly
   58     vminfo            kswapd_high_wmark_hit_quickly

These correspond to the entries in /proc/vmstat and you can now intercept
calls to them, e.g.


$ dtrace -n pgmajfault
...

I will attempt to update the release to fix the broken earlier kernels
shortly.

(Getting the /proc/vmstats stuff involves examining an enum and isnt amenable
to #ifdef coding practise, so I may need to autodetect which ones are
available for the current kernel).

Post created by CRiSP v10.0.17a-b6101

Linux! How Dare you?!

2011-10-26T13:45:00.001-07:00

Strange. I had started work on proving the vminfo provider. It
was very close to showing results.

Then I hit a strange problem. One of those "Duh!" moments.

So, to check out the vminfo provider, I need to run dtrace to intercept
the probes. But the kernel kept panicing.

Heres the panic:


[  458.807224] kernel tried to execute NX-protected page - exploit attempt? (uid: 0)

Didnt make sense. It worked a moment ago. Or so I thought.

So next, lets downgrade our probe. We *know* syscalls work because I had
tried that on getting the Ubuntu 11.10 release and validating on the 3.0 kernel.
Lets try something different:


$ dtrace -n fbt::sys_chdir:

(Given a choice of 250,000 probes to choose, I want one, I *know* exists without
looking up, and one which is executed rarely, preferably, on demand). Yup.
This dies too.

Ok, so revert the code to the last release. Repeat. Panic.

Strange.

Lets try a random.other.kernel (Ubuntu 10.04). No problem.

What?!

Ok, the Linux kernel guys are smart. Very smart. What did they do?

They changed the way a kernel is mapped into memory. Previously, all
kernel pages were pretty much executable (especially .data/.bss). This was
unnecessary and they appear to have fixed this. Dtrace does something slightly
suboptimal - a char[] array is declared for executing the breakpoint
trampolines, but this is a BSS symbol. And the page the structure resides in
is no longer executable.

*That* explains why it suddenly broke on the latest kernels. The fix
is easy: just mark the page as executable. I would like to use the
proper API or GCC __attribute__ specifier, but the API calls are problematic -
some are GPL-only exports; others dont expose the pgprot permissions etc.
The "lets modify the page table directly" approach seems to work.

So, I'll release a new dtrace which fixes this problem (and hopefully
a working vminfo provider too).

Post created by CRiSP v10.0.17a-b6101

dtrace update - attempting the vminfo probe

2011-10-25T15:15:00.001-07:00

I've started tackling the vminfo probe provider, which is effectively
an SDT probe - statically compiled into the kernel. The approach is a
hands-off on the kernel source, but I have a tactic which I hope
will work.

Theres some issues, such as slightly different code for 32 vs 64 bit
kernel, but the approach seems sound.

In effect, this is a google map of the kernel binary - searching the
kernel for the instructions which represent increments to the
vmstat data counters, and enabling them for probes.

Will report back in a while if this looks good enough to use.
Many of the other providers are similar in style, but there are some
issues, such as not all counters in the kernel follow the vmstat
pattern. There is also the issue of provider function names
matching Solaris (some will, some will be extras). And also the callback
arguments need to match Solaris spec or something useful (more troublesome).

Post created by CRiSP v10.0.17a-b6101

iOS5 .. some thoughts

2011-10-21T15:46:00.001-07:00

Having used iOS5 for a week or two now, I thought I would add
my thoughts.

Wins: iPod Touch - they finally fixed the bug where switching away
from video and back, does not take 5+s to figure out whats going on.
Thanks. I appreciate that. Only taken 2years to fix.

Loss: Watching videos on the iPad is an exercise in frustration. I dont
get why Movies and TV Series are different. With Movies, I can
tell what the movie is (my ripper adds a front screen and title). But
for TV Series, all I see is an array of images for all tv series.
I cannot tell which is which. Please ! Why cant a title be added?
I have to guess which one I want and drill down to see what it really
is.

Worse, they removed support for having playlists of TV Series sitting
in the ipod playlists section. So, there is no text to navigate what to
see.

Why is the iPod and iPad different?

Next: iTunes. I like iTunes - its not bad. Its not good either.
The most recent release disallows selecting a selection of music
tracks and editing the displayed image. Previously I could go to,
for example, Amazon, and drag/drop the cover art into the Get-Info
popup. This doesnt work when multiple tracks are selected.

Its always a gamble with iOS and iTunes whether the next release
is retrograde or forward thinking.

Not being able to have a "guest" ipod/ipad so you can selectively copy,
e.g. home videos to a relatives device, is another bad point.

On the plus side, if Apple had gotten this right, we wouldnt talk about
them so much.

Oh, and the 64GB phone! At last. A phone with 64GB. Android cannot
compete. I wish Google and the device manufacturers could find a place
for people who want to load lots of video onto a device. Shame that
Apples phone price is so high.

Best to wait til next year to see if we get SDXC or 128GB device
support in a phone.

Post created by CRiSP v10.0.17a-b6092

CRiSP and FCTerm

2011-10-21T15:15:00.001-07:00

People may wander why I keep mentioning fcterm and CRiSP
when they are really waiting for dtrace. Well, consider it an
advert - dtrace is the "draw-in", but CRiSP is the product.

What is CRiSP? Its an editor. Its been my hobby horse for so
long now, that its old enough to be married, have children,
and you can find it hanging out in bars, wondering why it
didnt listen to its Daddy and get a decent job.

Its been relatively stagnant for a while - I had run out of things
to implement and support.

CRiSP is a multiplatform editor, before that was de-riguer. It
runs on Windows/Mac/Linux, and is pure C code. Its small and
tight in terms of code (by todays measuring sticks).

Fcterm - is a color terminal xterm. Started many many moons ago
when Sun brought out SunOS 3.x, and color monitors were just starting
to appear. In those days, "shelltool" and "cmdtool" and the whole
XView desktop was just too "black and white". Color xterms didnt
really exist (AIX had a nice one). So, fcterm was born. It
was small and fast.

As CPUs have gotten faster and faster, its still small and fast, but
over recent years it has had new features added (infinite scroll,
graphical drawing ability). (See prior post on "proc" using this
to effect -- http://crtags.blogspot.com/2011/08/some-illustrations-of-proc.html).

Theres a limit to how much you can add to an xterm. Or is there.

See below for a screen shot of the latest fcterm. This is character
mode crisp running inside the window, providing graphical features
(also available in the graphical version of CRiSP). I spend
most of my time in an xterm - the Ctrl-Z/fg aspect of switching from
editing to "doing" is convenient, and its worth making the terminal
emulator comfortable.

[fcterm has a butt-ugly popup window for setting attributes; on my
todo list to revamp that one day].

Look carefully at the outlining margin and the gridlines for tab
indenting.

Post created by CRiSP v10.0.17a-b6092

80pixels

2011-10-20T15:34:00.001-07:00

My "new" laptop has developed a HW fault on the screen. (A band around 80pixels
high, about 1/3rd of the way down). I can still use the laptop but have to
move the visibility of what i am doing out of the zone.

Although Dell have a sophisticated web site, it is sub-par when
it comes to reporting a fault. Following the various strands on the web
disallows you from having an online chat to figure out how to actually
report the fault. A pay-phone number will be expensive, and will have
to do that tomorrow.

The "Lets download a plugin and sod-you if you are not on Windows
or are using Firefox" is very offensive. Customer care is really an
after thought.

At least Dell have a twitter feed (@DellCares) which is potentially good
but probably a time waster - in wanting details, sprawled out over
hours of waiting for replies and using terse abbreviations (which
is understandable given twitters 140 char length).

Its really very comical - that a company the size of DELL with
a sophisticated web site (which I hate and like at the same time),
have to "breathe through a straw" to communicate with customers and
not use the interactive IM mechanism they have on their site.

My banding on the screen went from 1-pixel high to about 60-80 pixels.
Oh well. Why does this happen 6 months into the laptop and not after
2-3 years (which I so desperately wanted my old one to do, so I could
justify this one!).

Post created by CRiSP v10.0.17a-b6085

DTrace and GIT

2011-10-18T13:55:00.001-07:00

I have had a few emails about "where is the latest dtrace?" despite
it being posted on every web page I maintain, and provide the lowest common
denominator - tarballs! Such a nice word :-)

People ask, cant I do "git"? Well...simple answer is "no". There
is a unmaintained(?) dtrace github page, but it wasnt set up by me,
but an enthusiastic supporter.

I can understand people either wanting to track changes or make
contributions.

So, I am opening up the conversation to people: Just how badly can
I damage GIT ?!

I have recently started using GIT and automating the commits at home,
but I am lacking an understanding of git and how to cope with complexity.

Heres the deal. In theory I have two main machines - a server,
rarely switched on, but the "master", and my laptop, where I do most
of my work -- manually syncing changes (not just dtrace, but
for CRiSP and other things) across the machines.

I set up git on my master and laptop ($HOME/git) and use symlinks in
my source code dirs so that the git repository is in its own tree.

Previously, I would just create periodic tarballs as snapshots -
which are mostly fine, but not necessarily synchronised to the sync points.

I rsync my laptop/master git repositories - probably a bad thing. Is it?

So, if an external facing git repository is available, what does it
achieve?

Q1: I can sync to the external repository from my internal, and stop doing
tarballs? (Or keep doing both).

Q2: Who can touch the git repo? Presumably whoever I permission, or, is
it a free-for-all?

Q3: Assuming its a trusted circle of people, then how do I sync
from the repo back to my local git repo?

I really want to review what people do and likely not
accept some contributions or recode them to fit in with my "style".

I dont want to be a Linus/Git-meister (but will if need be - if it
helps the greater good).

So, educate me or be gentle with me.

(I am busy adding some new features to CRiSP and fcterm to show
outline grids whilst editing, and when I finish this, I may go back to
Dtrace and start to remember "What was I planning to do next").

Post created by CRiSP v10.0.17a-b6082

Dtrace on Ubuntu 11.10

2011-10-14T13:49:00.001-07:00

Now I figured out the issue on Ubuntu 11.04, a few minutes later, I can
prove it appears to work on 11.10 - with the new Linux 3.0 kernel.

So, thats a relief.

(Hm. Why did I make such a basic typo above which spoilt the meaning? Why did someone have to post it to me?!)

Post created by CRiSP v10.0.16a-b6074

Dtrace fixed for Ubuntu 11.04

2011-10-14T13:33:00.001-07:00

I reported yesterday that dtrace had suddenly broke on my Ubuntu 11.04 release.
Now resolved.

At some point in the recent past, /proc/kallsyms was layered in
security. Looking at the file as a non-root user means we dont
have access to the symbol table (all values are zero). We fell
over in a heap since we couldnt find the right places to patch
in the kernel.

My sillyness really - as either I should run "make load" (or tools/load.pl)
as root, or be more careful when symbol lookups fail. The
script and driver dont handle the null pointers to well.

Simple fix is to shroud the opening of /proc/kallsyms by a call
to sudo.

Put up a new release to fix this.

Post created by CRiSP v10.0.16a-b6074

Dtrace updates..

2011-10-13T15:00:00.001-07:00

Dtrace has been quiet lately, as I fix up some other things.

The recent news about Oracle doing Dtrace has generated a bit more
interest in Dtrace, along with some support issues. I put out a couple
of minor fixes for later kernels.

I just tried dtrace on my Ubuntu 11.04 release (the day that 11.10 has
come out), and it paniced my kernel. Strange, because it did work a while
ago, although I havent done heavy bare metal usage (I do get bored watching
Linux/KDE reboot :-) ).

So, am downloading the 11.04 and 11.10 ISOs to give them the VM treatment
and see what gives.

Post created by CRiSP v10.0.16a-b6074

DTrace update...sort of.

2011-10-07T12:15:00.001-07:00

Just pushed out a minor update to fix a problem on SLES11 systems.

Its a few days after OracleWorld and the Dtrace announcement and
people may bump into this blog because of Adam Leventhals post.

So, just a few words on the Dtrace/Linux port which has been available
for 2+ years now.

From what I understand Oracle are planning to port Dtrace to Linux, despite
this release being available. That is a *good* thing, because it
means a 4th (to my knowledge) port of Dtrace. First was FreeBSD, then
there was MacOSX, then there was this Linux/Dtrace.

I have learnt a lot from reviewing and understanding the differing
implementations. My work on Dtrace is "not-bad" if I am going to self-rate.
It is mired in details to do with multiple kernel support and lack of
source code modifications to a kernel: Dtrace/Linux is simply a loadable
kernel module.

Oracle will pick up the latest code of Dtrace from the Solaris area,
and will have some fiddliness to insert into Linux. They
pay their employees to do this - and thats great. They can change
the kernel source code, and provide a value added kernel (just
like Google does with Android and all the other hardware/software
vendors who leverage Linux).

This will presumably give them a competitive advantage: for those
customers who want Dtrace, then Oracle potentially looks attractive.
Many people in the Linux community will write-off Oracle as "not team
players". That happened before, with Sun. This leads to healthy,
sometimes silly but entertaining debates on the interweb.

Since Oracle is not using this port of Dtrace as the basis of their
work, does not imply the death of this project. The likelihood is
more people will stumble upon it and lead to more support questions or
requests to finish or fix issues.

Oracle could add new providers to the kernel - and this release of
Dtrace will not be able to match these, without patching kernel source.
I dont know how this will evolve. Maybe Oracle will show us what to do;
maybe there will be sufficient impetus to get dtrace into the master Linux
kernel, but I doubt that will happen.

The GPL vs CDDL debate still rages. I've written numerous times on
my opinion of the debate (namely, I dont have an opinion!).

So continue to try/play with Dtrace.

Post created by CRiSP v10.0.16a-b6073

Dtrace on linux and Oracle?

2011-10-04T14:02:00.001-07:00

Great news today - everyone is talking about Oracle shipping DTrace
on the next Oracle Linux release.

Whilst Oracle are not seen as the great open-source giver-aways,
this can only be good.

I have no inside knowledge on DTrace for Oracle, and twitter (http://twitter.com/#!/search/%23dtrace)
has references to people rejoicing or denouncing it.

Is dtrace battle hardened for production use? No. One person
isnt going to prove that DTrace works everywhere for everyone on every
kernel version. I have tried; one gets bogged down in details, especially
for legacy releases and the myriads of distros that have inconsistent
packages and package names.

It works (mostly) for me; I know it crashes on a 16-core box occasionally.
(Alas, I dont have a 16-core box. Maybe its the 48GB of RAM which is the
issue rather than the number of cores, which affects the page table
layout of that system).

As anyone knows who manages software projects, a software project
manager probably does little "coding" .. the closer to completion
of the project, the harder and more required it is to reach
100% perfection. Ask Linus. I dont know how much real coding vs
patching/merging/overseeing he does.

Even the big-guns out there, like RedHat and Oracle - much of the
time and expense is tracking down bugs. There are a few people
who add value. This is what software engineering is about. Finding
your place, and managing those around you to optimise delivery.

I dont know what Oracle is doing; even if its a closed-wall, there
are benefits. When Apple introduced DTrace, it did a great job of
allowing them to fix and optimise and understand their own systems. Sure,
it wasnt perfect in the early days.

So, lets see if Oracle can influence.

From what I read, Adam Leventhal has been experimenting with
adding kernel probes to the Linux source. Even if this is the only
thing he has done, then its a great news banner. I'm loathe to walk
that plank knowing that maintaining such deltas is difficult when you
are not a part of a key release. Maybe if Ubuntu or RedHat or someone
would offer to allow such merges in, it would be fun to add them.

Solaris has hundreds/thousands of probe points, added over the last
5+ years. Each would have required consideration about what to measure,
whether the correct probes were in the right places, and supporting/testing
them. Probe-dropping is laborious and nobody will thank you for
those probes. A lot of people will benefit when "it just works".

So, lets see what happens.

And why have I been quiet recently? Well, various other mini projects
needed to be addressed. "proc" is one of them; I am not happy with it as
yet - sometimes the results seem to be suspicious, but it does look good.

But my recent project is to update CRiSP a little. Now it is supporting
grids/gridlines, so you can see the true structure of a file.

Keep watching.

Post created by CRiSP v10.0.15a-b6064

Some illustrations of "proc"

2011-08-10T14:24:00.002-07:00

These partial screen shots show "proc" in action. Its still a work in progress. See the prior post for more background on "proc", and download the package and look at the README.

Two new tools..well old ones. Revamped

2011-08-10T14:24:00.001-07:00

"top" is a great tool - very old. And lacking in many ways, 20+years after
it first appeared.

"proc" is my version of top. I wrote it many many years ago for Solaris,
so it could do what *I* wanted. I've had this tool for a long time. I
ported it to Linux, and have been happy with it.

Why is it better? Because it does color. It crams more data into the
screen real estate. It uses a better sorting algorithm (there are lots
to choose from), and highlights memory deltas.

"proc" is available from my tools area (next door to dtrace).

Why am I bothering to talk about proc?

Because I realised as CPUs get faster, and with 8 cores on an i7,
drilling down and understanding whats going on in a system requires
more esoteric tools.

So, whats wrong with "proc"? For one thing, its easy to see something
on screen which is of interest, but, on the next screen update, it might have
disappeared. This can be annoying - as machines get bigger, more
processes running, the screen real estate cannot show everything at once.
Sometimes you want to go *backwards* and rewind what you just saw.

Well, that requires a bit of re-engineering. But its done. By default
you can cycle back upto 20 mins of history. History is stored in
/tmp/proc; by the time we factor in the process table, the amount of
data is quite staggering (about 1GB of data per hour). This includes
the key process attributes, along with extensions for /proc/pid/wchan,
/proc/pid/stack etc. (Nearly everything is kept, but not absolutely everything;
e.g. signal masks are not stored). And this includes the threads.

We also keep /proc/meminfo, /proc/vmstat and many more.

Theres so much data, that actually visually monitoring it is quite
difficult. Just staring at /proc/meminfo has so many fields,
one cannot understand/comprehend what is happening from one second
to the next.

Even with history, its not comprehendable.

So, the second major update to "proc" is graphics. The ability
to see, in graphical format, what is happening to the various key stats
is very educational and illuminating.

The implementation of graphs is interesting. Rather than creating
an X11 application or KDE or GNOME, I decided to implement this
inside the terminal emulator. "fcterm" is my emulator of choice -
and fcterm was recently enhanced to support various escape sequences to
do line and rectangle drawing. By using simple printf/escape-sequences,
anything can be drawn - sufficient for drawing graphs.

[I have a sampler in the fcterm/ctw distribution, available on
my site, written in Perl, to show just about every /proc entry
as a graph. Its crude, but effective, but quickly shows that dumping
all graphs onto a page just overwhelms; that is why proc was enhanced].

I have just uploaded proc-b21, for you to play with (but you must
use it inside fcterm; I havent validated what it does in another
xterm). It is still a work in progress, so dont bother reporting
bugs to me yet.

I will upload a few images in the next blog post.

Post created by CRiSP v10.0.13a-b6043

Virginmedia Tivo

2011-08-06T14:20:00.001-07:00

Sometimes, I dont understand the web. If you read the reviews
of Virginmedias Tivo product, they all rave about how good it is.

But it isnt. The interface is buggy and designed by people who havent
tried to read the text from across a living room, even on a big screen.

The fact that you cannot archive programs from the device without
watching the same program on the main TV is, well, somewhat myopic.

The ethernet and USB interfaces do nothing (as yet). Why? Its 2011.
(I think I know why, because the film industry doesnt want people to watch
films away from a DRM controlled environment).

The on-demand and catch-up services are badly thought out and confusing.

The remote control is as bad as all other remote controls - it
cannot be held in the hand and used in a one-handed mode - not if you
are fast forwarding.

The fast forward on tivo is very badly thought out and confusing.
Its idea of fast forward is 2x or 3x. One cannot quickly scroll
through without a lot of button pressing. (The jump in 10min
intervals is broken and confusing).

The suggestions do not understand recording and watching something -
it only seems to work based on thumbs up/down.

Tivo does not understand a family who have different tastes and
preferences.

The YouTube app is a joke. Watching 240x320 youtube videos in
degraded quality on a 40" TV is about as ugly as you can get.

http://virgintivo.blogspot.com/2011/07/virgin-media-ceo-tivo-impact-will-equal.html

The above is typical of the glowing self-satisfying reports on
the product. Multi-room streaming? How will that work? If that means I
can watch tivo on my PC in another room, then I am salivating.

If it means I can watch one tivo from another room, then think on! Who
is going to have two Tivos in a household?

Applications on the tivo are just a real joke. On the ipad,
applications are great because it allows a degree of 'context'
without having everything coming through the browser.

BTW the virgin Android TV guide app is poor. Very poor. It is welcomed -
it is better than nothing, but it is one of those 'why am I wasting
storage space on my device' apps. (You can control your
tivo device from this app, to do remote recordings; but theres a serious
glitch in the way it works - you cannot record a program if it is
on in less than 35mins from now. Why?)

The tivo is 'not bad' but its certainly not a step up from the
prior Virgin+ device.

Post created by CRiSP v10.0.13a-b6043

cpu visualisation

2011-07-22T15:33:00.001-07:00

Its quite interesting to contemplate different ways of looking at
things.

I have an Intel i7 machine - its fast (its a laptop, so it could be
faster if I had a desktop CPU).

Linux provides a lot of raw data, but one thing that "top" lacks is
more detailed info. There are display widgets for KDE and GNOME
which help you visualise cpu load, but this display shows something
interesting:


last pid: 4792 in: 4448 load avg: 1.28 0.71 0.43                      23:21:45
CPU: 8(HT)  @ 2.00GHz, proc:231, thr:464, zombies: 1, stopped: 5, running: 3 [t
dixxy:  7.3% usr, 0.1% nice, 1.5% sys, 84.6% idle, 6.4% iow, 0.1% sirq
RAM:7918M RSS:0K Free:303M Cached:1913M Dirty: 664K Swap:225M Free:7878M
cpu
Intel(R) Core(TM) i7-2630QM CPU @ 2.00GHz
          usr   nice    sys   idle    iow    irq   sirq  steal  guest  gnice
CPU0     8.4%   0.0%   2.6%  73.6%  15.2%   0.0%   0.8%   0.0%   0.0%   0.0%
CPU1    63.6%   0.0%   1.8%  21.0%  14.2%   0.0%   0.0%   0.0%   0.0%   0.0%
CPU2     0.2%   0.0%   1.0%  99.2%   0.0%   0.0%   0.2%   0.0%   0.0%   0.0%
CPU3     2.4%   0.0%   1.0%  97.0%   0.4%   0.0%   0.0%   0.0%   0.0%   0.0%
CPU4     0.0%   0.2%   0.2% 101.0%   0.0%   0.0%   0.0%   0.0%   0.0%   0.0%
CPU5     0.0%   0.0%   0.2% 100.2%   0.0%   0.0%   0.0%   0.0%   0.0%   0.0%
CPU6     0.2%   0.0%   0.8%  99.4%   0.2%   0.0%   0.0%   0.0%   0.0%   0.0%
CPU7     0.0%   0.2%   0.6%  98.6%   1.2%   0.0%   0.0%   0.0%   0.0%   0.0%

           MHz    Cache  Bogomips
CPU0  2001.000  6144 KB  3990.88
CPU1  1400.000  6144 KB  3990.92
CPU2   800.000  6144 KB  3990.97
CPU3   800.000  6144 KB  3990.93
CPU4   800.000  6144 KB  3990.96
CPU5   800.000  6144 KB  3990.96
CPU6   800.000  6144 KB  3990.94
CPU7   800.000  6144 KB  3990.98


The info is taken from /proc/cpuinfo (this is the "proc" utility - available
at my website; run it and type 'cpu' at the command line to see this
display).

Note that CPU0 is running at 2GHz - to be expected, although slightly strange.
Its strange because this represents the cpu that the proc command
is instantaneously running on. It doesnt use much cpu, but the cpu
has adjusted the clock to give it speed. (Note that, as an i7, this
CPU should be able to ramp up to 2.9GHz but I havent seen evidence in
/proc/cpuinfo this occurs).

Note also that cpus 2-7 are idle (800MHz is the lowest speed
without actually sleeping).

CPU1 is running at 1.4GHz - I have a backup job running in another
window. The question is - *what is cpu1?* I presume its the
hyperthreaded cpu, and therefore should run slower than cpu0. Ideally,
jobs should run on: cpu0, cpu2, cpu4, cpu6, cpu1, cpu3, cpu5, cpu7, in that
order.

The question in my mind - what is hyperthreading -- is it an attribute
of the cpu, which is fixed, or does it meander from one cpu to another.
If the hyperthreaded sibling is solely virtual, then one can deduce
that for this system, we should get unequal performance as the 5th cpu
is made to do work.

I just did a test (seeing how many "counts" we can do per second), and
ran 5 of them in parallel. Certainly, one of them was not as busy as
the other 4. [This was not a good test, since the counter-loop doesnt
exercise cache-misses and hyperthread ability, but solely relies
on the Linux scheduler to run the processes].

Definitely requires more investigation to understand the effects.

Post created by CRiSP v10.0.12a-b6036

warning! warning! warning! In the beginning was more. Then there was less.

2011-07-19T14:21:00.001-07:00

In the very old days of computing, you could sit in front of a screen
or a teletype and watch the output, a character at a time.
110 baud or 300 baud was eminently readable.

As output devices progress to 9600 baud serial lines, one could fill
a screen in a second (80x24). And "cat" or "make" on its own was
not good enough to read the text frantically scrolling off the screen.

Zoom forward a few years, and with todays multi-GHz cpus and fast
screens, one can 'cat' a 10MB file in a few seconds to the screen.

Did you see the error on line 12,723,104 ? No? Didnt think so.

Tools like "more" and "less" are great for paging slowly
through a file and allow searching and backwards motion.

Or, one can use an editor, such as vim/emacs/CRiSP.

These are great.

When building software, e.g. with gcc/g++, and as projects have
gotten bigger, it can be difficult to spot an error in the middle
of a huge amount of benign output. Worse, gcc has a tendency to
overdo the warnings. Scrolling in an xterm to review the output is
frustrating, trying to spot the magic "error" in the midst of warnings
(or other output).

There are many solutions (such as viewing the output in "more" or "less",
and relying on highlighting to find the item you are after). "less" can
do highlight, but "more" cannot. CRiSP can do highlighting too.

fcterm (my own personal terminal emulator) can do this too, but
you have to tell it what to search for. (I must modify it to have
a default set of words - having a single search pattern is not good enough).

I wrote a simple tool called "warn". You use it like this:


$ warn make
...

and all error output lines are shown in red, with warnings in yellow.
(My default console is green on black).

Very useful for spotting the wood for the trees.

I havent released it as a standalone tool (it has bare minimum
requirements - its plain C code). If people are interested, I will put it
out.

Next up is to fix fcterm...

Post created by CRiSP v10.0.12a-b6034

What is the meaning of 1?

2011-07-17T07:03:00.001-07:00

Timestamp: 2011-07-17 12:59:11
Title: What does '1' mean?
Body:
In the context of load average on a system, a load avg of 1 is
something meaningful, if you are on a single cpu system. It represents
the cpu is busy, continuously.

Now consider multicore/multicpu machines. A load avg of 1 is not
quite so meaningful. On Linux, the load average represents a moving
average of processes which are blocking. It slows ramps up and ramps
down.

Doing heavy duty work (like parallel compilation) means that "gmake -j"
doesnt have enough information to determine if the system is busy.

In the old days, when a source file compilation could take many seconds
or minutes, the load average told us what the system was doing.

On an 8-core (Intel i7) cpu, doing 'gmake -j' can invoke
tens of parallel compilations, yet, 'top' can show the system as
being idle, because the load average takes a while to ramp up.

On an 8-core system, with one cpu being busy, should we say 'the system is
busy' (system usage == 100%), or should we say it is idle (system usage == 12.5%)?

The answer depends on what you are measuring and how you want to handle
it. If 1 out of 8 cpus is busy (maybe the application is broken and
stuck, and eating cpu continuously), then that is important. The
system may be busy, but noticing that rogue application is useful.
Ignoring it until all 8 cores are busy may never happen.

An additional complexity is that on a totally idle system, a single
CPU can ramp up the clock speed; but if that cpu is not doing useful
work, then the second cpu may not be able to ramp up as high, and
get worse performance.

In the end, what is useful is to notice one or more processes
'behaving badly', e.g. consuming too much cpu, or too many failed
syscalls, or too much I/O.

Today top (or my application, 'proc') does not readily show that, but
that needs to change.

dtrace gripe

2011-07-13T14:38:00.001-07:00

I really dislike some aspects of dtrace. Its a great tool,
but the "lets pretend we are C" when it isnt is a nuisance.
Macro languages should be designed to be expressive, but
dtraces' D language is annoying.

Firstly, the lack of if-then-else is a problem. It leads to
convoluted use of ?: (which cannot handle multiple statements).
I really dont understand why if-then-else isnt there. It doesnt
harm the "Thou shalt not have loops" which can lock up a kernel.

Whats annoying is that the C programming language, and D, copying it,
does it to an extent that is .. well, annoying !

Consider this: I want a probe which can exit after 5s of execution
time. Heres the naive implementation:


BEGIN {
	t = timestamp;
	}
tick-1ms {
	timestamp - t > 5*1000*1000*1000 ? exit(0) : 1;
}

This isnt possible, because exit(0) is a void function.


BEGIN {
	t = timestamp;
	}
tick-1ms {
	timestamp - t > 5*1000*1000*1000 ? (int) exit(0) : 1;
}

But, oh-no! You cannot cast a "void" to an "int". In C, I can understand
that (almost) but it leads to painful workarounds. In D, there is even
less reason: if a (void) could be cast to "(int) 0", then the above
would work. Its still ugly, but functional.

The actual solution is:


BEGIN {
	t = timestamp;
	}
tick-1ms / timestamp - t > 5*1000*1000*1000 / {
	exit(0);
}

Which is fine - although I havent determined if the predicate is
worse or more expensive than the actual code. What is annoying is that
the predicate is a "different part of the language". What if I wanted
to do this:


tick-1ms {
	do-some-stuff;
	if (var > somevalue) { printf("hello"); exit(0);}
	do-some-more-stuff;
	if (var > someOthervalue) {printf("world"); }
	...
}

This can be translated into predicate format, but this can involve
ugliness in performing the transformation, especially if the do-stuff
lines of code are complex in themselves.

Its time to start addressing these deficiencies in Dtrace (at the risk
of being non-standard extensions to the true code).

Post created by CRiSP v10.0.12a-b6033

CRiSP website updated

2011-07-12T13:51:00.001-07:00

After many years of staring at abject ugliness,
http://www.crisp.demon.co.uk has been given a lick of paint, more in tune
with the blog site in terms
of look and feel and stylesheet.

I have updated some of the very dated things, and hope to update it more
so.

Obligatory plug: you can now purchase CRiSP (via paypal) if you so
choose.

Post created by CRiSP v10.0.12a-b6033

dtrace update

2011-06-20T15:10:00.001-07:00

I've updated dtrace to slightly improve the xcall code. Having tried
on an AS5 kernel - hit some other issues.

Some build issues are fixed (2.6.18 kernels confuse the syscall
extraction code); it mostly works - but some warnings are present.
Additionally, a 'dtrace -n syscall:::' will crash the kernel. I suspect
some mismatch on the ptregs syscalls and/or 32b syscalls on this kernel.
Need to debug.

Also found that on 16-core machine, the xcall code leads to a lot
of noise when things arent the way it expects. This eventually led
to an assertion failure in dtrace.c (on a buffer switch - which is
in agreement that the dtrace_sync() didnt hit the expected cpus, i.e.
some race condition/bug), and eventually a failure from the kernel that
a vm_free was invalid.

Oh dear.

To date I have been testing on dual-core cpus. I need to get an i7
so I can ramp up to 8 cores and do more heavy torture tests.

So, keep an eye out for updates (which are likely to be slow in
coming in next week or two), whilst I hopefully try to refine
the xcall issue.

Post created by CRiSP v10.0.12a-b6033

NMI support added

2011-06-19T14:17:00.001-07:00

I modified the cross-cpu call code to allow use of the NMI interrupt
when the IPI interrupt is not responding. Hopefully this will avoid
the xcall code from busting a lock due to a deadlock/timeout.

It looks like the APIC allows specific interrupts to be marked as
NMI - which would be great since rather than sharing the NMI with
other users of the interrupt, we could just make the IPI interrupt
work like an NMI and avoid the deadlock scenario.

For now, the interrupt handler tries to be careful and not trigger
when its uncalled for. It does present a problem if we need the NMI
and someone else does at the same time, but I can investigate what/how
the APIC works a little better (or check the Solaris code to see
if indeed, that is what it does).

I also need to update the dtrace_linux.c code so that I dont just
grab interrupt vector 0xea (random interrupt which appears not to be
used, but it could be). I am a naughty programmer.

Release 20110619 contains the above fixes.

Post created by CRiSP v10.0.12a-b6033

The Final Phase of dtrace

2011-06-19T04:56:00.001-07:00

I have been writing about the issues of inter cpu cross function
calls (xcall) - a key part of dtrace. This feature isnt used very
often, but its an important part of SMP to ensure consistency in
accessing buffers.

After a lot of effort, writing, rewriting and rewriting yet again, the
code is (nearly) finished. It looks good - it handles arbitrary
cpus calling into other cpus and allows for a xcall to be interrupted
by another call to xcall (effectively a mesh of NCPU * NCPU callers).

However, I have found a flaw. If I modify the dtrace_sync() function
to sync 100-200 times instead of just once, then occasionally there are delays
and kernel printk()s from the code - where spinlocks are taking too long.

Turns out, we could deadlock if we try to invoke an IPI on another
CPU which has interrupts disabled. Not totally sure how Solaris handles
this - I get a little lost in the maze of mutex_enter() and splx() code.

There is a solution to take us to the next level - NMI - the NMI interrupt
is not maskable (unless an NMI is in progress). NMIs are typically used
by Linux for a watchdog facility - make sure CPUs arent locking up, as
well as "danger signals" (like ECC/parity memory errors).

I will experiment to see if I can run via an NMI rather than a normal
interrupt and that should help reduce the problems of lock-busting
significantly.

At the moment dtrace is pretty good - my ultra-torture tests really
are horrible, and most people wont do that in real life.

So, as always, tread carefully until *you* feel happy this is not
going to panic your production system.

Post created by CRiSP v10.0.12a-b6033

Update to prior post

2011-06-16T15:24:00.001-07:00

My findings in the prior post are not strictly the end of the story.
Subsequent to this, I found that I needed to resort to the cmpxchg
instructions to beef up the resilience of dtrace_xcalls. Current
results look good.

More testing to follow and I need to fix AS4 (Linux 2.6.9) kernel
compilation issues.

Post created by CRiSP v10.0.12a-b6030

DTrace xcall issue -- fixed? Website of the day.

2011-06-16T12:14:00.001-07:00

http://forum.osdev.org/viewtopic.php?f=1&t=21768&start=0

Now, this has been driving me nuts for months. Why was my spanking new
cross-cpu code hanging occasionally? I had spent ages building up
the courage to write it, and was fairly proud of it. But it just
wasnt relilable enough and I disabled it in recent releases of dtrace.

Heres the problem: a cross-cpu synchronisation call is needed in dtrace.
Not often, but in key components. I feel like the way this was done in
dtrace was almost laziness, because there are other ways to achieve
this (I believe). But the single cross call (in dtrace_sync()) is
a problem...

Interestingly, I was surprised it was called so often. Its called
during the tear-down of /usr/bin/dtrace as the process exits. I had
wondered why dtrace intercepts ^C and doesnt die immediately. It
does something very curious - it intercepts ^C and asks the driver nicely
to tear down the probes we may have set up. Of course, you can kill -9
the process, and it works. *But*. *But*. If you do that the probes
arent torn down! Instead, they are left running. After about 20-30s,
since nothing in user land empties the buffers, the kernel auto
garbage collects, but it means on a kill -9 scenario, whatever
you were tracing may continue to take effect.

I dont like the way ^C works in dtrace and I may attempt to fix it
(eg fork a child to tear down the probes; tear down is done by a STOP
ioctl(), btw).

Ok - so cross calls happen a lot especially during tear down (and also
during timer/tick interrupt handling).

So .. what happens? Well, on a two cpu system, the cpu invoking
cross call deadlocks against the other cpu waiting for the remote
procedure call to be acknowledged.

With the original Linux smp_call_function() there were lots of issues
in calling it with interrupts disabled (ie from the timer tick interrupt).
This is not allowed - two cpus calling each other at the same time
will deadlock.

The cross-call code has to run with interrupts enabled and that
means being very careful with reentrancy and mutual invocation.

One day I put some debug into the code to try and spot mutual or
nested invocations and I got a hit. On a real machine. But never on
my VMs.

I modified the code to allow a break-out - after too long waiting, the
code gives up and allows the machine to stay in tact. Without this, the
machine would lock up (deadlock with interrupts disabled).

I fixed the code to handle mutual invocation and recursion.

But I could not figure out what the locked-up CPU was doing. I tried
to get stack dumps from the locked CPU - but these would only happen
after dtrace had given up waiting. Its as if the other CPU was asleep
and wouldnt wake up until the primary CPU had given up looking
(a definite Heisenbug!).

The web link at the top of this page illustrates the exact same
setup I was seeing. So, I followed the page (it tells that
acknowledging an end of interrupt to the APIC too prematurely may not
work on a VM).

Not only had I spent a huge amount of time to understand, fix and engineer
a solution but I almost had a working solution without realising it.
I had moved the APIC_EOI code to the end of the interrupt routine
previously, but because of the lack of support for mutual invocation, it
hadnt worked. So I put it back again.

So I think this is looking good - much better than before. I need
to do more torture testing and cleanup before I release.

On the way, I tried or started trying with lots of things
(like using a crash dump to analyse this problem .. which wasnt
successful). Or, using NMI interrupts instead of normal interrupts.
I've learnt a lot and been frustrated by a lot too along the way.

Keep an eye on twitter .. I'll report a status update if I think
I am not close enough.

Post created by CRiSP v10.0.12a-b6030

My blogs

2011-06-12T09:21:00.001-07:00

Just reading Nigel Smiths Blog (http://nwsmith.blogspot.com/), which
has a nice back-reference to this blog and dtrace.

People may find my blogs a bit confusing. I thought it worth detailing "why".

Originally I set up a series of blog posts, using my own Perl blog code,
which was in turn, based on the nanoblogger code.
(http://nanoblogger.sourceforge.net/).

The website I publish to (www.crisp.demon.co.uk) is interesting in itself.
Demon was the first ISP in the UK (back in early 1990s) to offer access
to the Internet. Alas, they have never done anything useful since then,
and I pay subscriptions for a near-useless service (teeny amount of
web space, no perl or cli or anything else). Because space is so tight,
I tend to leave most things, including CRiSP and Dtrace downloads on my
internet facing machine at home. The only thing that Demon usefully
serves me is the email address, although I do try to get people to switch
to my (numerous) gmail accounts.

I was using the Dyndns service for a DNS entry but due to some sillyness
on my behalf, I lost the name entry, which put dtrace off the map
for many people. I reinstated a new address (via crisp.dyndns-server.com).

I should just pay for a normal DNS entry but I havent decided what I want.

The crisp.demon.co.uk is costly, much more costly than a decent hosted
web applicance, so I do need to do something.

At home, I have two main dev machines - and when I blog post, I try to
update both the original Demon hosted site, and also blogger. It turns
out to be easier to update blogspot first, and the Demon at a later
date when I "get around to it". ("Get around to it" means powering on
my main PC, running a script, and shutting it down again). Things
got confused because I have two dev machines and have to be careful how
I sync to and from each other.

So, thats the feeble excuse for me appearing and disappearing in
the waves.

Post created by CRiSP v10.0.11a-b6022

dtrace progress

2011-06-11T02:00:00.001-07:00

Been continuing work to increase resilience of dtrace. One thing
I found was that there are some syscalls which have differing
calling sequence compared to the others (fork, clone, sigreturn, execve
and a few others).

Bear in mind when we think of a kernel - there are multiple
views of the kernel:


  - 64b kernel running 64b apps
  - 32b kernel running 32b apps
  - 64b kernel running 32b apps

The apps get to the kernel via system calls. System calls are implemented
in a variety of ways - depending on the kernel version and the
CPU. (Some older cpus, such as i386, i486 dont support instructions
like SYSCALL, SYSENTER).

So dtrace traps the system calls by patching the system call table.
The code is mostly the same but subtley different for a 32b and 64b
kernel.

But when a 32b app is running on a 64b kernel - the app doesnt know
any different, but the kernel does. The kernel has two system call
tables: the system call, for eg. "open" is a different index on the
two OS's. The two OS's developed differently. i386 kernels have
had to maintain backwards compatibility, but the amd64 kernel did not
and started afresh at the point these cpus became available.

Dtrace handles that.

Except it didnt handle the special syscalls: when a 32b app invokes
fork(), clone(), etc, we usually ended up panicing the kernel.

Most Linux distros are "pure": a 64b distro has 64b apps, so you
rarely see the effect of a 32b app.

Linux/dtrace has a nice interface for system calls. The probe name, e.g.


$ dtrace -n syscall:::

matches all system calls. But the 32b and 64b calls are different probes.
So, you can intercept all 32b syscalls on a 64b system:


$ dtrace -n syscall:x32::

which is useful in many ways.

I have nearly fixed these special syscalls on the 64b kernel - just
have clone() to fix. The symptom of not fixing is a cascade of
kernel OOPs and panics (because the kernel stack layout is not
what it should be).

I hope to release later today a fix for this problem.

Post created by CRiSP v10.0.10a-b6012

dtrace -- some updates

2011-06-05T13:37:00.001-07:00

After spending a lot of effort on the xcall issue, I had hit an issue
where occasionally, system calls would fail. The regression
test shows this up by running a perl script which continuously
opens an existing and a non-existing file, plus a variety of other things.

Very occasionally, Perl would emit a warning relating to a file handle
being referred to which belong to a file which couldnt be opened.
(/etc/hosts - which always exists).

Similarly, other apps would occasionally fail to start with rtld
linker errors.

This proved very hard to track down: I was pretty certain it was
related to the xcall work I was doing. The error rates were rare - less
than 1 in a million, and almost impossible to track down.

I moved away from xcall debugging and found that by having two
simple perl scripts (on a dual core machine), which continuously opened
files and nothing else, that the error rate would increase whilst
the two scripts ran.

To try and get a better handle on this, I moved from 64-bit kernel
debugging to 32-bit kernel, where the error rate was significantly
higher.

After a lot of experimentation, it transpired that the error wasnt to do
with xcall, but the syscall provider. Specifically, a piece of
assembler glue turned out to be rubbish. I am not sure why it appeared to
work, but it didnt. (I had made some changes earlier on which may
have broken the syscall tracing on 32-bit kernels).

After recoding the assembler glue - things looked much better. The
errors in syscall processing appeared to be gone. But a new problem
surfaced - one I wasnt too surprised to see. There are a handful
of 32-bit syscalls which use a differing calling convention to the others.
(The 64-bit code handles this, but not the 32-bit code).

I have nearly finished redoing the 32-bit syscall tracing, and, once
done, will need to validate the 64-bit syscall tracing.

If I am lucky, hopefully in the next few days or weeks, the resiliency
issues will disappear and I can put out a new release.

The syscall tracing code is horribly ugly - because we have to support
different calling conventions across the two types of cpu architecture.
I may split the code up into an x86 and x86_64 code file.

Post created by CRiSP v10.0.11a-b6022

Bad websites

2011-06-02T14:03:00.001-07:00

Bad websites. Whats with them?

I have a beef with a variety of websites - nice websites, let down by the
"We dont care attitude" or "We didnt test it".

http://www.tvguide.co.uk

I despair of this web site. Its a great guide to TV channels for UK
people. Nice layout. Lots of content.

So, whats wrong with it?

A number of things. One - the menu bar at the top of the screen is over
engineered. If you try to do something, like select one of the sub-menu items,
the ability to navigate and not lose context is near impossible. Try and
select something, e.g. "New series". I leave you to find which submenu
thats under (a minor annoyance).

Secondly, the huge amount of real estate given over to pointless banners.
These arent advertising banners, but program banners. On a small screen
you have no information content on the first screen at all. On a large screen
you barely get 50% of your screen with the TV grid.

The search function is badly over engineered using javascript.

And if you turn off some ad sites via an ad-blocker, the whole page becomes non-functional.

And lastly, the page quite often forgets who you are and your
channel selections.

I gave up with this site, and wrote my own TV highlighting application.

BBC RadioTimes

The BBC provides XML files containing 14 days of TV schedules. This is
a great source of data (which I use in my TV planning application).

But the reviews are *awful*. No, make that, *truly awful*. When I see
a film or a series of potential interest, the paragraph of review is of
this form:


This film, made by XXX YYY, is a follow on to his earlier work ZZZ, AAA, BBB.
The director did blah, and the actors did bloop. The film won an award at
Cannes, and went straight to video.

Can you tell whats wrong with the above? Its totally devoid of any information
about what the film or program is *about*. The reviews/write-ups on
tvguide.co.uk at least tell you what the program is about.

Heres a real quote from the BBC:


One of two low-budget westerns made by Barbara Stanwyck - the other was 
1956's The Maverick Queen - before she found her glorious late-career 
stride with such titles as Forty Guns and TV's The Big Valley. 
Aided by thoughtful direction from the prolific and talented Allan Dwan, 
this movie now has great curiosity value, in that the leading man is 
former US president Ronald Reagan, a bland and colourless performer 
when pitted against screen villains Gene Evans and Jack Elam. 
The location scenery is very attractive, the action sequences 
well staged, and Stanwyck as tough as ever: it's a shame the 
script didn't give her or any of the cast more opportunities. 
Still, this will pass the time nicely, and teenage girls might 
discover a useful role model.

Gizmodo.com

My first site of the day is http://www.dailymail.co.uk. Yes, I know - thats
a poor choice of a news website, but consider it bubblegum for the
brain first thing in the morning. My second is
Engadget. A very nice
and highly fluid website with news stories of interest to me.

And this, *was* Gizmodo. But I have removed the link from my web browser.

On my ipad, I have a cached page dating back to April - I cannot get it to
update. I dont know what they did. On my other devices, I dont have the
caching problem. Gizmodo used to track Engadget in style and content.
But recently, they have overhauled it. And they have not done any
user testing as far as I can tell.

First, I would be redirected to the mobile site, even though I dont
want that. Now, they have reformatted the website, and its totally
devoid of content on the front page.

It used to work and be a great site, but I waste my monthly bandwidth
quota vising Gizmodo and hoping for something useful to browse.

So, goodbye to Gizmodo. Maybe, when others start linking to it again
and it contains useful content (even if its a rehash of other sites),
I will revisit.

Slashdot

This site has been great for years. Until now. The pool of people powered
news stories they have is great. But slashdot have been playing games
with their presentation and - as my 4th choice of read of the day - is
close to being binned as well.

For starters, the three column format is annoying. Very annoying.
When browsing on a mobile/small screen device, the left hand column
requires you to scroll the screen to view the text. I never look at the
left hand column - because I know it never changes. So why waste prime
real estate with that, *there*.

Next. Slashdot has tried to create slow and large home page loads. I applaud
that. But they have done that by limiting the number of visible stories
to about 6. Given that they seem to dribble items out at about once
per hour, that means its pointless visiting the site
repeatedly during the day. And if you leave it too long, you lose
continuity of stories you have read/not-read. (You have to scroll
to the bottom of the screen, click on "More", wait, wait, and
then you see the stories you saw a few hours ago).

Slashdot seems to have "lost it" - it used to be an interesting
place to read non-news stories, about technology, but they have
taken the Gizmodo approach - reduce the amount of useful info
on the page to the point where visiting it has taken on a boring
attitude.

BBC

BBC - what a poor website. It used to be awful. Now it is pointless.
Another home page devoid of content. Its full of flash cleverness where
you can edit the layout, but I dont want to do that. I want to see news.
The news page is devoid of information - almost like it is a commodity
which is in short supply.

(Compare the BBC news defaults with the Dailymail website - theres enough
information in each paragraph on Dailymail to decide if you
want to read further. On BBC, you have to guess if the news item says
anything useful).

Next, try reading BBC on a mobile device. The customisations do not work
(at least, not on my android device). The site is untested in real life.
I rarely look at BBC - every few years when I look, I think the same thing.
A waste.

There *is* good content on the BBC site - if you spend the time to find
the programme schedule and radio information. But using the BBC website
is like having an unfaithful lover: things move around so much you are
never sure if the site will be the same when you visit it. It would not
be so bad if it got better when the changes happen. But it gets worse.

The real-estate vs information content is so low, that it reminds me
of the days of a Teletype (ASR-33 with a paper punch drive).

Can I do better?

I dont for one moment think I can do better than these sites. I have
learnt lots of interesting things (both in terms of content and in
terms of presentation). But the dilution of news sites which
all feed off each other, has made the internet quite boring.

Which is a shame.

Post created by CRiSP v10.0.10a-b6012

dtrace update 20110531

2011-05-31T13:30:00.001-07:00

Its been a while since I put out a dtrace update and thought it
worthwhile to give a brief update of what is annoying me.

The most annoying thing in dtrace at the moment is me. I have spent
the last two months trying hard to resolve some resilience issues.

At the moment, there are two of them: (1) is the xcall code, and
the other is (2) something to do with syscall tracing.

As related on prior blogs, the mapping of dtrace_xcall() (which
does inter-cpu synchronisation), doesnt map to Linux very well. On
Solaris, the inter-cpu calling code works from interrupt context,
but we cannot do that in Linux. (Linux will write a warning to
the /var/log/messages files when this happens - although it does mostly
work).

I have tried a number of variants of a native IPI system in dtrace and
they have failed with various problems. The biggest problem is that
on an SMP system, cpu#1 will invoke a call to cpu#2 but cpu#2 wont respond
until cpu#1 finishes the xcall (a deadlock). In the code, I have
resolved the deadlock by giving up after a suitable period of time,
but thats not good enough. Trying to find out what cpu#2 is doing
when it refuses to respond to the interrupt is very tricky. Various
ad-hoc debug tricks (like using the native smp_call_function() to dump
stacks) failed. Additionally, the synchronous order of messages
written to /var/log/messages is horrendous when I am doing my implementation
of xcall - the cpus write out of order with timestamps going backwards.
(I can understand why, but it doesnt help).

I have given up resolving the SMP cross-call issue: and instead have
been trying something different. The only place where the
xcall issue is a problem is the profile/tick provider hr_timer clock
interrupts. So I have modified the code to use a tasklet structure instead.
This seems to work (I have some race condition problem to fix before I
can release it).

But, during all this testing, I hit another strange and annoying scenario.
Doing:


$ dtrace -n syscall:::

and doing intensive things in another window, like:


$ while true ; do date ; done
...
date: error while loading shared libraries: /lib64/ld-linux-x86-64.so.2: cannot apply additional memory protection after relocation: Error 9
...

Very occasionally, a system barfs. I have seen the output from dtrace
hang (it hangs until I press a key on the keyboard). I have tracked
this down : when a write() syscall is being executed, its being
turned into a read() syscall.

The event is very rare - 1 in hundreds of thousands of syscalls, but its
horrible. And its *this* problem which is likely what prompted me to go
on the xcall wild-goose chase. The "make test" regression suite is very
good at pushing the cpu load to the max whilst doing dtrace things, but
it occasionally would have issues.

So, if I can chase the 1:100,000 issue in syscall tracing, then I can
move forward. (I suspect a timer interrupt coming in during a syscall might
be causing the issue).

As always, I will release the code when I feel its better than where
we are.

Post created by CRiSP v10.0.10a-b6012

Dtrace progress - update on xcall

2011-05-20T15:27:00.001-07:00

I have spent the last few weeks on trying to perfect the dtrace_xcall
emulation. Its quite possible I have been wasting my time and/or
looking at the wrong problem and solution.

What is dtrace_xcall? Very occasionally, dtrace needs to broadcast to the
other CPUs to ensure they are in sync. Typically this happens when
shutting down the user space application as the trace buffers need to be
dropped, but happens under other scenarios.

Solaris provides a cross cpu function mechanism, as does Linux.
But they do not work the same.

On later Linux kernels, you may see a BUG warning in the
kernel logs, like this:


[  245.215564] WARNING: at kernel/smp.c:421 smp_call_function_many+0x69/0x1b9()

This is the kernel being nice, and warning that the smp_call_function_many()
function is being abused -- specifically being called from an interrupt
routine.

The problem is to do with locking and rescheduling should delays happen.
At worst, this can lead to deadlock and a hang of the system you are using.

In practise, this problem is rare - but that is not good enough.
Dtrace needs to be rock solid. As part of the distro, I include a
torture test ("make test") which tries various things, whilst putting
excessive load on the system (forked processes, opening files and doing
things which I have found to cause problems on earlier dtrace releases).

The test runs well, despite the problem described above, but
very occasionally, one sees horrible "failed to open shlib" type errors
as Linux applications are spawned - rare, but enough to demonstrate we
are doing something wrong and/or have race and locking problems.

In reviewing carefully the Solaris code, and the Linux code, I have
tried about 3 algorithms to resolve the problem. The latest code
is good, and is a fairly close emulation of what Solaris does, but
it is difficult to prove correctness. In this latest code, the
driver allocates its own distinct interrupt vector, and uses this to
send an inter-cpu interrupt (IPI), whilst spin locking waiting for the
other CPUs to complete.

It works real well, except occasionally - an attempt to raise an interrupt
on the other cpus fails, and we have deadlock. I put some counters
and delays into the code and some "get out of jail" logic to avoid
total machine hang, but thats not good enough. I have tried various
other hacks, but it is demonstrable that we ask an interrupt be fired
and sometimes it never arrives. This, I fear is me not fully understanding
how the APIC works or having interference with other interrupt sources.

But an important question in all of this is why do we get
that BUG warning, as illustrated above?

The reason is the timer interrupt. If you use the tick/profile probes to
get periodic probes (and even if you do not), the clock will fire
and occasionally this will happen whilst a probe is being serviced.
(You get dtrace timer interrupts even without the use of the
profile provider, since dtrace internally uses this for deadlock or
lack of system responsiveness detection). The more probes you fire
the higher the chance of collision.

Add to this the complexity of a multicpu system, and debugging is very
difficult. One of the most difficult things to do is to see what another
CPU is doing from another. Its easy to litter the driver code
with printk() tracing, and to generate a stack trace when interesting events
happen - but doing this for another cpu to see what/where it is stuck is
not easy (or, at least, I havent found simple code to do it - I am sure
its doable, since the kernel provides support via SYSRQ to do this, but,
possible using the same smp_call_function_many calls we are trying to debug).

But - back to the timer interrupt -- should they even be happening?

I am about to research this: dtrace_probe() disables interrupts during
operation, so the CPU invoking this function cannot have a reentrancy problem.

But the cyclic timer code eventually invokes the dtrace_xcall function:


[  245.215564]  <IRQ>  [<ffffffff8104d9ad>] warn_slowpath_common+0x85/0x9d
[  245.215564]  [<ffffffffa02472d6>] ? dtrace_sync_func+0x0/0xb [dtracedrv]
[  245.215564]  [<ffffffffa02472d6>] ? dtrace_sync_func+0x0/0xb [dtracedrv]
[  245.215564]  [<ffffffff8104d9df>] warn_slowpath_null+0x1a/0x1c
[  245.215564]  [<ffffffff81077c34>] smp_call_function_many+0x69/0x1b9
[  245.215564]  [<ffffffffa02472d6>] ? dtrace_sync_func+0x0/0xb [dtracedrv]
[  245.215564]  [<ffffffff81077da6>] smp_call_function+0x22/0x26
[  245.215564]  [<ffffffffa025575d>] orig_dtrace_xcall+0x35/0x4b [dtracedrv]
[  245.215564]  [<ffffffffa0255a85>] dtrace_xcall+0xe/0x1b [dtracedrv]
[  245.215564]  [<ffffffffa0248c9f>] dtrace_sync+0x1a/0x1c [dtracedrv]
[  245.215564]  [<ffffffffa022f9cc>] dtrace_state_deadman+0x46/0x89 [dtracedrv]
[  245.215564]  [<ffffffffa022c875>] be_callback+0x1d/0x2f [dtracedrv]
[  245.215564]  [<ffffffff810692ed>] __run_hrtimer+0xbb/0x143
[  245.215564]  [<ffffffffa022c858>] ? be_callback+0x0/0x2f [dtracedrv]
[  245.215564]  [<ffffffff81069aa6>] hrtimer_interrupt+0xd4/0x1b3
[  245.215564]  [<ffffffff8146ff95>] smp_apic_timer_interrupt+0x79/0x8c
[  245.215564]  [<ffffffff8100a693>] apic_timer_interrupt+0x13/0x20
[  245.215564]  <EOI>  [<ffffffff81397010>] ? read_pmtmr+0x10/0x17
[  245.215564]  [<ffffffff81397025>] acpi_pm_read+0xe/0x12
[  245.215564]  [<ffffffff8106dce9>] timekeeping_get_ns+0x1b/0x3d
[  245.215564]  [<ffffffff8106e1ce>] getnstimeofday+0x54/0x89
[  245.215564]  [<ffffffff81065f2c>] sys_clock_gettime+0x61/0x90
[  245.215564]  [<ffffffff81009cf2>] system_call_fastpath+0x16/0x1b

So, now I question whether the invocation of a timer interrupt
should invoke a direct call into dtrace, or whether this should be
queued up and deferred. I am 50:50 on this - deferring would imply
complication which doesnt appear in the dtrace code. Its possible
that in the non-dtrace Solaris code, this scenario is handled in the interrupt
handlers - maybe some form of decouple of the interrupt from the
probe firing. (I cant figure out if/how that can be done, without
the kernel doing occasional checks).

It is possible that Solaris (and MacOS) are both broken and that
it is possible for the system to be deadlocked, but I havent
found evidence this can happen - so, somehow, this is resolved.

(Note that dtrace linux takes some cheap shortcuts in the hrtimer
code and avoids some of the complexity of the cycle timer code - I havent
understood enough of the details to see what it does and if we need it
in Linux; maybe eventually for accurate and non-skewable clock sources).

Before I release a new dtrace, I need to decide what to do with some
of the experimental code (presently, there is missing code on the i386
side, and issues with older kernel compilations, along with a bit of
dirtyness in stealing an interrupt rather than properly allocating one
via the kernel APIs).

If anyone is still reading this, you can occasionally pick up private
beta releases (dtrace-tmp.tar.bz2) in the dtrace ftp dir, but I dont
advise touching these - as the code will be in an indeterminate state
along with too much debugging enabled.

Post created by CRiSP v10.0.10a-b6012

dtrace update -- xcall interim

2011-05-10T15:28:00.001-07:00

I hope I have this fixed - am just trying to prove the quality of the
implementation. I'll write up the experimentation and results another
day when I have time.

I have implemented my own interprocess function call interrupt because
the Linux one isnt viable from within an interrupt routine.

Post created by CRiSP v10.0.9a-b6004

Trials and Tribulations of Dtrace

2011-05-02T13:21:00.001-07:00

I reported a while back about the issue with cross-cpu function
calls (via the smp_call_function() series of functions).

On Solaris, the way dtrace_xcall() works is to invoke an inter-cpu
interrupt in order to ensure the CPUs are in sync with certain data structures.

Alas, on Linux, the smp_call_function's are not callable from an interrupt
routine. Unluckily, this is necessary and can cause the systems to
deadlock / hang, whilst dtrace breaks the API call.

I tried an alternate implementation of dtrace_xcall() using timers,
but found problems in getting this to work.

I tried a 3rd variant - not invoking cross-cpu calls, but, instead
executing the cross-cpu call 'on-behalf-of' the current cpu. This
looks more promising, but requires putting a mutex (actually, a spin-lock)
around the dtrace_probe function, to avoid one cpu executing a probe, whilst
another cpu is doing the housework to clean up.

This does look better, but I am currently having rare scenarios
where some syscalls can break: a repeated series of process forks can
occasionally give rise to a problem mmap-ing one of the shared libraries.
This is very difficult to debug - as many millions of calls can work
correctly, before one of them fails.

By "thinking about the problem" it is likely that some form of stack
or register corruption is happening somewhere. What might be worse is
CPU cache consistency issues happening - I am fearful of cache consistency
issues being very difficult to debug, but lets see what happens.

I have put extra debug code into dtrace to try and spot the issues.

There is another approach which is to intercept the NMI interrupt which
is where IPI interrupts come from, but I need to think this one through
before attempting this.

Post created by CRiSP v10.0.7a-b5984

Natty Ubuntu - n.i.c.e !

2011-04-30T11:34:00.001-07:00

After a year of Ubuntu failing to work with suspend-to-ram (despite
upgrading kernels, debugging the powersave etc), it now works in 11.04.

Thank you!

My only report of dislike is that iwconfig broke in this release.
My prior command to set up the wifi stopped working and took a number
of rereadings of the man page to figure out what was wrong.


iwconfig eth1 key XXXXXX

Firstly, my wifi changed from wlan0 to eth1. But the key was not being
allowed no matter what I tried. I eventually did this:


iwconfig eth1 key XXXXXX '[1]'

and that fixed it. Strange. Ubuntu 11.04 is a 2.6.38.3 kernel - the same
kernel I had previously (or maybe it is 2.6.38.8 - am a bit confused
what it did to my /boot and /usr/src directory).

Just found they broke my googlecli install. Had to reinstall python-gdata
and the googlecl package to allow me to blog post again.

Post created by CRiSP v10.0.7a-b5984

CRiSP Adding gridlines support

2011-04-29T08:56:00.001-07:00

I've added support for gridlines - which show you a line denotating
the indentation structure of the file you are editing. Its interesting
because what should just be a 'here it is' feature turns into a possible
feature with lots of sub-options.

I have added a 'set [no]gridlines' command as an interim to turn it
on/off, so I can become comfortable with what it shows me.

This is an alternative to the 'ruler' which is more 'in your face' in the
way the display is done.

Post created by CRiSP v10.0.7a-b5983

Sometimes, things are too fast.

2011-04-26T13:26:00.001-07:00

As machines have gotten faster and networks better, one doesnt notice
those annoying things which happen in this non-perfect world.

I have been using X11 CRiSP over a transatlantic link and the
startup time is annoying, along with visible artefacts whilst drawing
the color gradients.

On investigation, the problem is our old-friend: latency. Some
X11 function calls block, waiting for a reply from the server, e.g.
querying color pixel mappings being the core one. The gradient and
pixmap drawing code relies on lots of color allocations, forcing
round trips - large numbers of them.

On a locally connected machine or network, this happens so fast, you
rarely notice it.

CRiSP was written back when monochrome displays were common - certainly
color was a very rare thing. Today, we luxuriate in 24/32 bit video
displays and rarely even think about it.

So, these round trips are pointless when we know what the RGB
mapping will be - no more XQueryColors, or even XAllocColor.

Doing this has a dramatic performance enhancement for these
long latency trips. (You wont notice the speedup on a local
machine - not unless you use special measuring tools).

The first part of this went into CRiSP 10.0.6, and the pixmap
enhancements in 10.0.7.

[Note, I am dropping the trailing letter in CRiSP version numbers -
they never served a real purpose, and people sometimes forget to
feed this back on error reports; the build number tells me everything
I need to track back to specific source code changes].

At the moment, this feature is enabled by setting an environment
variable:


$ export CR_XS_DIRECT=1

http://www.crisp.demon.co.uk/download.html

Post created by CRiSP v10.0.7a-b5977

Dtrace bugs

2011-04-24T03:11:00.001-07:00

Hm. Dtrace has a lot of bugs in it...as I try to ensure dtrace
cannot crash the linux kernel, I am stumbling on to some "thinko"
errors in dtrace.

Try the following on a Mac:


$ dtrace -l >/dev/null & dtrace -l >/dev/null & dtrace -l >/dev/null & dtrace -l >/dev/null &

We get interrupted system calls and issues on the major/minor numbers
(see 'dmesg' after it fails).

Next up is DTRACE_ENABLEIOC. This calls dtrace_copyin_dof() which validates
the main dtrace mutex is not asserted. Normally it isnt, unless someone
else is running a heavy handed probe trace, in which case a nasty race
condition exists. Unless a VFS lock is applied, this could spell out
danger or kernel panic (on Solaris, FreeBSD and MacOS).

dtrace_xcall is another area of potential for kernel deadlock if
multiple dtraces are firing on multiple cpus.

I have nearly finished my "safety" checks in dtrace, having written
my own dtrace_xcall, and am checking that kernels dont deadlock on you.

But its uncovering some nasty race conditions in dtrace as a whole.

Post created by CRiSP v10.0.5a-b5971

How does this work? (wifi)

2011-04-22T14:31:00.001-07:00

Very strange. For *months* (in fact, over a year) my laptop has worked
fine with the wifi router...occasionally lost connections when
the microwave is on.

Tonight, my wifi broke, totally, on my laptop. Spent last few hours
slaving over the system, a driver or two and all the config in the
world.

Today, was the day I threw out most of my old PCMCIA wifi cards. Typical.

Ok, out with the screwdrivers, take the back of the laptop off (and
learnt that my laptop can take two hard drives at the same time).

No joy. Niente. Nothing. Nada.

Same problem.

Use the Android phone to analyse the wifi around me.

Use the iwlist command to probe access routers around me. Someone must
have installed a new one.

Next....err....why does my startup script set the channel to 11,
yet iwlist is showing it on channel 6?!

Ok, so set the channel to 6. And Viola! It works.

Weird. Very weird.

If the channel was so wrong, how did it work at all?

Just dont *ever* assume I know what I am talking about.

Post created by CRiSP v10.0.5a-b5971

smp_call_function and dtrace_sync

2011-04-19T15:57:00.001-07:00

I've been reading Adam Leventhals (old) blog entry on the
IPI mechanism (inter-process interrupt) and how some of the
code in dtrace works in order to try and debug the Linux problem,
whereby the timer interrupt can invoke a call to dtrace_sync and hence
dtrace_xcall. dtrace_xcall in turn invokes smp_call_function() (and
its friends), but Linux explicitly disallows this behavior - calling
the function from an interrupt or whilst interrupts are disabled.

Linux's implementation seems ok. But it is at right angles to the Solaris
implementation. Solaris seems to have a higher level of semantics in
this area, allowing interrupt code to invoke inter-cpu synchronisations.

I have a question - and if anyone (Adam?) knows the answer, feel
free to educate me. Without an answer, I may have to wrap the
Linux APIC interrupt handlers with code that resembles Solaris.

What does dtrace_sync() *actually do*? In reading the code, it is trying
to ensure other cpus are synchronised in terms of the probe states,
but the implementation *looks wrong*. dtrace_sync() is a way of ensuring
that another cpu is either not running the dtrace code, or, if it is,
is at a sync point. But there are many sync points in the dtrace driver, and
no guarantee that the other cpus are anywhere close to where the invoking
cpu is asking for help.

Its a bit like a 3-dimensional goto - trying to prove safety via
the various code paths is not easy (maybe not possible).

Normally, mutex's are used to ensure guarded regions of code, along
with interrupt enable/disable, to prevent nested interrupts.

But dtrace_sync() is different - it suspends the invoking cpu
until the other cpus have acknowledged the interrupt - and the
acknowledgement is not done based on where the other cpus are.

The problem that dtrace/linux is having is mostly around the timer
interrupt - breaking the kernel contract on interrupts and
scheduling state. Its not possible (without hacking or damage) to conform
to the contract, which means I need to either stop using smp_call_function
or seek some other mechanism.

I need to sleep on this and work out the various permutations of
code paths.

[Note, I do have a safe workaround, but the workaround will cause the
odd timer tick drop within dtrace (the rest of the kernel is not affected).
I may have to release this as a temporary safe fix].

Post created by CRiSP v10.0.5a-b5971

opensuse .. and the differences

2011-04-18T13:35:00.001-07:00

The opensuse kernel is interesting. I am using this kernel:


2.6.31.14-0.6-desktop

Its caused me a few days of frustration, but I didnt want to be beat.
I have mostly cracked it now. The issue is around syscalls. The
way dtrace intercepts the system calls is by patching the system
call table. This normally points to the C code function to implement
the activity, and a small amount of assembler glue and C is used
to "hook" or "wrap" the system call.

One of the problems is that all system calls in dtrace go through
the same hooking code. When a system call is invoked, the %RAX register
contains the system call number, and dtrace assumed this register was
left intact.

It turns out it isnt. But why it isnt is interesting.

The opensuse kernel appears to be one of the most resilient kernels
to kernel crashes. Many a time an array of general protection faults
and illegal instruction traps fired, but I have rarely had to reboot
the VM.

Two things distinguish this kernel: DWARF stack walking and
stack protection. The opensuse kernel has a DWARF stack walker which
helps to ensure more accurate stacks are displayed when a fault
occurs. (Similar to the work I started, but to which I abandoned.
Maybe I can look at that code and see what style of approach they used).
[Stack walking is problematic generically, because of the 32 + 64 bit
kernels, along with all the permutations of GCC compiler switches
which makes it difficult to ensure the code base can handle these
variations].

The stack protection ensures that if a buffer overflow or some
other bad thing happens, then this is caught very fast.

The approach that GCC takes is to snapshot a random value
on the stack at the start of the function and validate the value
is still there on exit. This code utilises the %RAX register, which is
what was tickling my problem.

After various attempts to "jam" the uncorrupted %RAX into the C
arguments to the dtrace handler, I gave up. On 64-bit code, arguments
can be passed on the stack or via registers (the first 6 arguments only),
which means some degree of register fiddling, but also sensitivity
to compiler regimes and kernel compilation modes.

What I did was created a new per-cpu data structure so that
the %RAX register could be saved, without corruption by another cpu.
This data structure can then be used by the syscall wrapper code and
the results look good.

The existing systrace code has to handle 6 of the syscalls specially
(eg clone, fork and a few others), because, by definition, these
syscalls dont take the normal "exit" from the kernel route, but
hopefully I can fix these.

The next steps is to see if this "better" code works for the other
kernels I did not have problems with, and then to contemplate looking
at the 32-bit code implementation.

Hopefully, an update in a few days (or over the long weekend).

Post created by CRiSP v10.0.5a-b5969

Why?

2011-04-15T14:58:00.001-07:00

Why do people have to complicate something that was already
complicated already?

OpenSUSE 11.x - very nice system, very slow network gui configurator
(GUI network configurators drive me mad also - everyone is different,
none of them as good as the old fashioned SunOS /etc/rc.local files,
and all of them bloat. OpenSUSE cannot even have a settings control
panel that even looks familiar to any other operating system).

But my beef is the kernel source/images. Everyone has the
module include files in /lib/modules/`uname -r`/build/. Except
OpenSuse who has them in the /lib/modules/`uname -r`/source directory.
(Maybe they are available in the build/ dir if I had installed the
right extra package, but its like russian roulette trying to guess
where people have stored things or what the package names are).

apt-get, zypper, pkgadd, ... the list of names for proprietary package
installers is maddening. WTF is "zypper"? At least "pkgadd" hints what
it is. apt-get - which I am now familiar with, is standard across
many distros, yet the name of the package installer on Fedora eludes me.

Whilst I am bitching, what is "plymouth", what is "policykit", what is
"hald-runner", and the other ten zillion memory hogging wasteful utilities
on a Linux system? Go look for "plymouth" on google and see how well
you find references.

What happened to meaningful names. Even "dtrace" hints at what it might
be, and is unique to not clash with any other English word.

So....why do I care? Because I am setting up a new dual-core VM
to debug the smp_call_function issue. I think I know why smp_call_function
might be causing me erratic reliability issues, but I need a good
kernel to demonstrate/cause the bug I am trying to find.

Incidentally, I have turned up the clock ticks in the tests/tests.d script
to 1mS, to force a higher rate of clock-ticks interrupting caught probes to
help diagnose the tests. (I might even go higher - I want to torture
any system I come into contact with, because that is the only way
to validate interrupt-based coding systems; reading code or test-driven
scenarios can never handle the multi-dimensionality of interrupts occuring
at just the right + wrong points in time).

Post created by CRiSP v10.0.5a-b5969

smp_call_function and friends

2011-04-13T14:11:00.001-07:00

Dtrace has one reliability bug in it - which affects multicore cpus.
I have tried hard to get the reliability up in recent releases, torture
testing the code on various linux platforms - many survive very well, some
dont.

The torture test involves use of copyinstr() against an argument which is
not a string pointer. Good ones to test are fbt:::return, where the
argN parameters are whatever is left on the stack or in registers.
Dereferencing these lead to kernel level GPF or page faults.
Dtrace should be resilient to these.

Yet, it still can crash.

Some kernels are better at handling this than others - the later releases
generally have better interrupt handling routines or BUG_ON warnings
which log a message when a driver breaks a programming contract.

Which brings us to smp_call_function and it friends. From day 1, these
functions caused me pain; fortunately, Linux provides a set of these
functions, very similar to Solaris, so we won, handsomely.

Or didnt.

What are they? On a multicpu system, it is sometimes necessary for
drivers to invoke synchronisation barriers on other cpus. Typically
an SMP kernel and driver will utilise arrays of structures - one per cpu,
so that each cpu can process work independent of what another cpu is doing.
In the case of dtrace, we may be handling an fbt trap on one cpu, whilst
another is doing a system call. As the number of cpus goes up, the permutation
of scenarios of user code, kernel code, drivers, shared structures, etc
goes up.

What does dtrace do to warrant inter-cpu function calls?

Well, dtrace, the user space program works by periodically polling
the driver for trace information. Each cpu utilises a double-buffering
approach for tracing: traps and probes are recorded in an event buffer.
When the buffer is full, it can switch to an alternate buffer. When
bin/dtrace asks for a buffer dump, the buffer is emptied, and dtrace
asks the kernel driver to switch to the alternate buffer - just like
video double buffering.

A single bin/dtrace is effectively asking for data from all cpus.
So, the cpu which takes the ioctl() to ask for the buffer dump has
to tell the other cpus to "empty their buffers". It could do this
by swizzling the pointers in the per-cpu buffer, but this is dangerous -
the other cpu may be executing code leveraging these things. You
cannot simply disable interrupts and lock them out with a normal
type of mutex (you could do, but the number of places to litter
mutex can be high). Instead, because this is so rare, the
smp_call_function functions are invoked to ask each CPU in turn to
do an action on behalf of the invoker. Its quite elegant.

This is all based around the APIC implementation on the Intel/AMD
cpus which provides a mechanism to send a forced-interrupt to another cpu.
The target cpu takes the interrupt (assuming interrupts are not presently
disabled on that cpu), performs the task, and exits the interrupt.

The Solaris and Linux implementations are similar, but different. That
difference hurts.

Ok, so now to the tricky bit. Consider at any point in time, what
is a cpu doing? It could be in user space, or kernel space. In kernel
space, interrupts may be enabled or disabled.

Lets consider kernel running with interrupts enabled - another cpu
invokes smp_call_function; the first cpu takes the interrupt and returns.

Now, Linux has a programming contract: when invoking the function, we
must honor the following contract (taken from comments in kernel/smp.c):


 * You must not call this function with disabled interrupts or from a
 * hardware interrupt handler or from a bottom half handler. Preemption
 * must be disabled when calling this function.

It is saying that the invoke of the function cannot be an interrupt
handler. Guess where (my) dtrace implementation invokes smp_call_function's
from? The hrtimer code. A timer callback, by definition, is an interrupt.
So, because of this contract, which we have broken, profile tick probes
can interrupt the kernel when it should not do, leading to either
kernel warnings, or, kernel deadlocks.

I recently attempted to avoid recursive dtrace probes, but if we are
not careful, we will lose timer tick probes, which can break
scripts. (My own regression tests, which terminates after 5s, never
terminate because the tick we need is discarded).

So, we need to fix this problem. The SMP function calls rely on a fair
amount of fabric to control the APICs and other cpu register masks, so
its not as simple as reimplementing the code to shield from
kernel artefacts.

So, I need to come up with a plan.

Post created by CRiSP v10.0.5a-b5969

Diary of a compiler bug

2011-04-10T13:13:00.001-07:00

I do hate compiler bugs. They waste a lot of time and energy realising
you have hit one. The quality of todays compilers are excellent, spurned
by automatic regression tests, and the vastness of code which users
want to compile.

GCC - an excellent compiler - has been around for many years. I think
I first learned of it back in 1987 or so, and not only has a huge number
of updates and releases, but works on nearly every CPU/OS combination ever
invented.

But, when you hit a problem with the compiler, you are hosed -- you
could report a bug, but this may be fruitless, especially when the compiler
version is quite a few years out of date.

Today, I hit a compiler bug causing strange behavior in Dtrace on Ubuntu 8.04,
using the gcc 4.2.4 compiler. Yes this is old, and there may be patches
for it, but who actually runs Ubuntu 8.04 today? Is my Ubuntu even
patched up to date? (No, it isnt).

And does this bug exist in many other prior/next compiler versions?

There isnt enough time in the world to validate this. So a kludge, but a nice
one, was applied:


if (dp->dtdo_rtype.dtdt_kind ==
    DIF_TYPE_STRING) {
	char c = '\0' + 1;
	int intuple = act->dta_intuple;
	size_t s;

	for (s = 0; s < size; s++) {
		if (c != '\0')
			c = dtrace_load8(val++);

#if linux	
		/***********************************************/
		/*   This  pointless  code,  which will never  */
		/*   fire,  is  to work around a gcc compiler  */
		/*   bug  which  causes  a page fault because  */
		/*   'act' gets overwritten. I havent exactly  */
		/*   figured  out  whats  going  on here, but  */
		/*   turning off optimisation (which is not a  */
		/*   good  plan  for  __dtrace_probe())  isnt  */
		/*   viable. I have seen this on Ubuntu 8.04,  */
		/*   gcc 4.2.4, i386.			       */
		/***********************************************/
		if (act == valoffs) {
			printk("defeat compiler bug! %p act=%p s=%x/%x %x %x\n", 
				&act, valoffs, end, act, s, size);
		}
#endif
		DTRACE_STORE(uint8_t, tomax,
		    valoffs++, c);

		if (c == '\0' && intuple)
			break;
	}

The above code is embedded into the middle of the very important dtrace_probe()
function. (Renamed to __dtrace_probe, to allow/detect re-entrancy problems,
which lead to finding this bug).

The code is too large to easily find this bug or refactor. I verified that
turning off optimisation avoids the bug, but thats not a good thing,
as per the comment above.

What seems to be going wrong is register allocation/spilling in the compiler.
I *hope* it only affects this code fragment, but its very difficult to tell.

The effect of the bug was to cause a key variable ("act") to be overwritten.
Fortunately, the kernel survived the subsequent panic/page-fault, but
its not comforting to have this happening in an unexpected way.

BTW I managed to nuke my first VM last night - Fedora Core 14. After
debugging something similar on FC14, I started getting strange filesystem
bugs. Even a reboot didnt fix things. I got annoyed and fsck'ed the root
filesystem manually, despite fsck telling me "this was a bad idea". And it
was right. Because of the LVM, i nuked the root filesystem, and had to reinstall.

I do love VMs - took less than an hour to recover (oh, I wish I had
snapshotted the filesystem first, but, well, you know, I didnt!)

New dtrace later tonite to fix the compiler issue above.

Post created by CRiSP v10.0.3b-b5955

Dtrace and the insane dtrace_probe_error call

2011-04-09T00:27:00.001-07:00

I wrote last night about how the Sun DTrace implementation seems to get
the passback of the error address wrong. Looking at the Apple/Darwin
implementation, they fixed this.

So, leveraging the fact that I am not insane, I can fix it to.

(Its possible that in looking at the Open Solaris implementation of
dtrace, its missing some key features, as I find it difficult to believe
real Solaris has this issue).

Post created by CRiSP v10.0.3b-b5955

Either I am insane or dtrace is... dtrace_probe_error()

2011-04-08T15:45:00.001-07:00

Inside the driver, when an address/fault occurs, a function called
dtrace_probe_error() is invoked. This recursively calls dtrace_probe()
to raise a probe against the ERROR probe. Nice.

Heres the function prototype for:


void dtrace_probe_error(dtrace_state_t *state, dtrace_epid_t epid, int which, int fault, int fltoffs, uintptr_t illval)

This function, which is (perversely) written in assembler in FreeBSD and Solaris,
calls dtrace_probe(). An additional arg is passed back to dtrace_probe --
the internal id of the ERROR probe (dtrace_probeid_error).

All good so far.

But - and its late here, maybe I am too tired - the number of arguments are
*wrong*. The last parameter passed to dtrace_probe() is the "illval" argument
which is the address of a faulting instruction.

Consider this D script:


        BEGIN
        {
                x = (int *)NULL;
                y = *x;
                trace(y);
        }

We should get an error from Dtrace telling us we tried to access address
0x0000. But in Linux, we get some other random value. This is because
we cannot pass in the illval address - we ran out of arguments (arg0..arg4).

*Yet* FreeBSD/Solaris pass in the extra arg anyway - one arg too many.

I need to read this more to understand what is going on.

Heres the solaris code:


        ENTRY(dtrace_probe_error)
        pushq   %rbp
        movq    %rsp, %rbp
        subq    $0x8, %rsp
        movq    %r9, (%rsp) # <=== what is this?!
        movq    %r8, %r9
        movq    %rcx, %r8
        movq    %rdx, %rcx
        movq    %rsi, %rdx
        movq    %rdi, %rsi
        movl    dtrace_probeid_error(%rip), %edi
        call    dtrace_probe
        addq    $0x8, %rsp
        leave
        ret

Post created by CRiSP v10.0.3b-b5955

New dtrace release

2011-04-06T14:27:00.001-07:00

This is an interim fix for the recent pgfault problem. A silly in the
handler meant we didnt restore the interrupt stack properly, resulting
in a hung/broken kernel if a bad probe function, such as copyinstr(arg0)
triggered a page fault.

Initial results look good - although I havent done a diverse validation across
my kernels, but it should boost dtrace usability.

I am seeing a lot of these on FC14, indicating some kernel API protocols
are not being conformed to...thats next on my list:


[  311.686851] BUG: sleeping function called from invalid context at arch/x86/mm/fault.c:1074
[  311.687789] in_atomic(): 0, irqs_disabled(): 1, pid: 2553, name: tests.pl
[  311.687789] Pid: 2553, comm: tests.pl Tainted: P      D W   2.6.35.6-45.fc14.x86_64 #1
[  311.687789] Call Trace:
[  311.687789]  [<ffffffff8103d12b>] __might_sleep+0xeb/0xf0
[  311.687789]  [<ffffffff8146c374>] do_page_fault+0x15c/0x265
[  311.687789]  [<ffffffff814697f5>] page_fault+0x25/0x30
[  311.687789]  [<ffffffffa023ddfe>] ? dt_try+0x0/0xa [dtracedrv]
[  311.687789]  [<ffffffffa021f0b2>] ? dtrace_load8+0x41/0x90 [dtracedrv]
[  311.687789]  [<ffffffffa022842b>] dtrace_probe+0x202b/0x2420 [dtracedrv]
[  311.687789]  [<ffffffff8111f4d1>] ? path_put+0x22/0x27
[  311.687789]  [<ffffffff811201e9>] ? putname+0x34/0x36
[  311.687789]  [<ffffffff81116511>] ? do_sys_open+0xfe/0x110
[  311.687789]  [<ffffffffa024011e>] dtrace_systrace_syscall2+0x208/0x21b [dtracedrv]
[  311.687789]  [<ffffffffa02402ab>] dtrace_systrace_syscall+0xb2/0xb4 [dtracedrv]
[  311.687789]  [<ffffffff81009cf2>] system_call_fastpath+0x16/0x1b

Post created by CRiSP v10.0.3b-b5955

Tales of an Interrupt -- ud2a

2011-04-04T12:53:00.001-07:00

Debugging interrupt routines is tiring - anything wrong and BOOM!

So, whilst enabling lots of fbt probes, I was finding AS4 kernels
dying on me. Didnt appear to happen on other kernels, but probably
could/would do.

On investigation, we had executed an invalid instruction. Weird, as
in theory, the dtrace disassembler should just *work*.

But it turns out that because Linux uses judicious use of inlined assembler
code, we had hit a problem. The BUG_ON macro in the kernel, used for
asserting broken behavior (typically of a driver), is implemented by
utilising an invalid instruction. The invalid instruction (UD2A) is great -
we handle that ok, but subsequent to this instruction is a 10 byte field
which encodes the file/linenumber of where the bug happened.

Interesting.

Rather than have the compiler embed lots of __FILE__ strings into the kernel
memory, the strings are uniquified and stored in a separate lookup table,
utilising tricks of the GCC compiler.

Of course, Solaris doesnt do this - and so the FBT code need not worry about
this. (But FreeBSD and MacOSX *could do* if they so choose).

A quick path to the prov_common.c file stops us tripping over and losing
sync with the instruction stream, and this fixes the problem with:


$ dtrace -n fbt::a*:

Post created by CRiSP v10.0.3b-b5955

dtrace update 20110403

2011-04-03T07:17:00.001-07:00

I've fixed the problem with etc/io.d and etc/sched.d causing runtime
errors on those platforms where we cannot compile ctfconvert. This
is only a partial fix, as its not acceptable to preclude ctfconvert
from being available. ctfconvert is important so we can access Linux
kernel structures from D scripts, and this impairs the ability of
dtrace to do interesting things. (On these platforms, fbt + syscall
are still available).

I've rewritten the interrupt routines for i386 and amd64 - the interrupts
are now heavily macro-ised, which will help with future support and should
fix some issues.

I note on one of my kernels, that the io::: provider will hang/crash
the kernel, so I need to validate what is causing this breakage.

I have added a better 'make test' which can be used to to some minor
stress testing, and will add more functional tests as I hit bugs.

Post created by CRiSP v10.0.3b-b5955

dtrace pgfault handling

2011-03-29T14:57:00.001-07:00

Just spent the last two weeks or so debugging one of those
"but it used to work!" bugs.

Heres the script:


$ dtrace -n syscall::open*:'{printf("%s", stringof(arg0));}'

It doesnt do anything useful - intercepts all the open system
calls, prints the name of the file to be opened. Because the
last part of the predicate is wildcarded, we match the "entry" and
"return" paths of the function.

On return from a function, arg0 and friends are mostly irrelevant, random
and pointless.

So - by doing this, stringof() is being called on a bogus pointer.
Which should lead to a GPF interrupt. This works well on the later
kernels.

But on RedHat AS4, it paniced the kernel.

After a lot of investigation, it transpires, on AS4, we are taking
a page fault, not a gpf. And my page fault handler was not handling
the fact that on a page fault, the CPU pushes an extra word on to the
stack.

So dtrace is/was dangerously unstable to rogue D scripts, like this one.

Very difficult to debug - because I would keep panicing the kernel
as I tried all sorts of experiments to locate the area of the problem
(the interrupt code and the C callback code). Having located most of the
problem to the interrupt code, it took quite a few days to work out what
was wrong (I was ignoring the extra word pushed on the taken fault).
But this was good - I had often stared at the Linux interrupt handlers
to understand the very subtle effect of how the traps are handled
vs the "struct pt_regs" layout. I was having problems with the pt_regs
pointer being "garbage" in the various dtrace pieces of code, and it
was because, even if I survived panicing the kernel, pt_regs was out
by one word.

Having exercised (exorcised) the code very hard, I feel much more confident
that a user cannot crash the kernel - just as Solaris had lead us to believe.

[I note that in the Solaris kernel, special code is in place in the
interrupt trade code (assembly), to determine if the CPU_DTRACE_NOFAULT
flag is set. This flag is set within the dtrace code to tell the
gpf/pgfault handler not to take the trap, but, to skip over the offending
instruction (which is most likely a MOV instruction)].

So, now we have a better handling of gpf + pgfault (although I still
worry if during the handling of a GPF, whether we can have a pgfault.
Not sure this matters, because if its *our* pgfault, then we only
skip over the offending instruction, we dont try to read other parts of
memory.

ctfconvert / libdwarf problems

Another fix I hope to have in this release is some improvements for
building which people are reporting to me, due to the changes in the
last release (stub dwarf.h added to the ctfconvert utility). AS4 doesnt
have a viable libdwarf.so library - so either I work out what it has
and patch the ctfconvert code, or add in a libdwarf release (which would
bloat the distro). The main problem here is we *need* ctfconvert if the
files in etc/*.d are to not cause a run-time syntax error, as kernel
structs are referred to in the translators.

I may have to patch the dtrace command to ignore such errors when
auto-inclusion is enabled when parsing user scripts.

Testing

Now I am getting more familiar with dtrace, I hope to include better
tests to avoid problems where things break. I probably wont enable this
in the next release, but definitely for the one after this.

Post created by CRiSP v10.0.3b-b5950

Why the ipad1 is better than the ipad2

2011-03-27T00:31:00.001-07:00

I feel sorry for people who have the ipad2. Despite its lighter weight,
faster cpu, cameras and other tech, the magnetic cover, it is no match
for an ipad1.

Why?

Our aging cat who has become slightly incontinent and in her last days,
decided to pee on my ipad1. Maybe she has a preference for Android, I dont
know. But the moleskin cover did a 100% job of avoiding damage or
leakage on the device. The (fake) moleskin cover, now washed and covered in
washing powder, detergent, soap, really doesnt care what you do to it.
It doesnt care what cats think about it. It just survives.

So there you have it. 1 out of 5 cats prefer ipad1 to ipad2.

And I shant leave my ipad on the floor, charging, waiting to be
used as a litter tray again.

Post created by CRiSP v10.0.3b-b5950

CRiSP, DTrace, and other technobabble

Blowfish

dtrace4linux - support and issues

Doing a dis-service to your fans

DTrace and the CPC provider

github #2

github

Its raining.

vmalloc_sync_all

Impossible progress

Free advertising! Get CRiSP Now!

Update on the impossible

Naughty naughty bug.

Here it gets interesting...

The Bombshell

Eh? Whaddya say?

The solution

The evidence

Dtrace progress on the impossible

VMWare Player .. nice

The 'Great Bug' of 2011/2012

Working Backwards

Lets patch the kernel

Lets give up?

More on the impossible

Debugging with VirtualBox

Is that the worst you can do ?

Happy New Year Dtrace...You ruined my Christmas

Dtrace / Ubuntu 11.10/i686

dtrace update

Your dtrace fell into my dtrace :-)

llquantify

Ding dong! Who's there? Anybody? Someone say hello!

Couple of tools

Losing my marbles, err..mutexes.

CRiSP 10.0.19

You locked me out! No I *didnt*.

Whats a nice byte doing in an instruction like this?

Dtrace and Ftrace : cross-modification

I am going nuts.

Slaphead time...

DTrace and the quest for resilience.

gcc 4.6.1

New dtrace release

1 in a million

Dtrace bugs...

NMI revisited

NMI #2

Dtrace and the NMI Interrupt

Dtrace .. new release

Scrollbars: Time to banish them

In..Out..In..Out..Shake it all about !

Dtrace fixed (hopefully)

Dtrace .. what a crock

Dtrace TCP Provider

How fast is fast?

Dtrace progress

Dtrace and printk()

Dtrace .. does it work. Yes. No. Yes. No. What?!

Dtrace release 20111026

Linux! How Dare you?!

dtrace update - attempting the vminfo probe

iOS5 .. some thoughts

CRiSP and FCTerm

80pixels

DTrace and GIT

Dtrace on Ubuntu 11.10

Dtrace fixed for Ubuntu 11.04

Dtrace updates..

DTrace update...sort of.

Dtrace on linux and Oracle?

Some illustrations of "proc"

Two new tools..well old ones. Revamped

Virginmedia Tivo

cpu visualisation

warning! warning! warning! In the beginning was more. Then there was less.

What is the meaning of 1?

dtrace gripe

CRiSP website updated

dtrace update

You locked me out! No I didnt.