mardi 10 mai 2011

Tracing Workshop '11

I assisted to the Tracing Workshop held at the École Polytechnique de Montréal on 9-10 may 2011, here are some highlights of the event. Partners presented their challenges followed by current research conducted in the fields from many Canadian universities.

Partners

Partners mentioned the interest in security, debugging hardware, real-time systems, embedded systems and large scale distributed infrastructure.

On the security aspects, the goal would be to increase the accuracy of detecting intrusion. It's reported that simple attacks are often working, like sending an email with a link that loads some browser extension or other web site, up to get the user credentials.

The need to model normal behavior and alert when the system is going outside of it without false positive has been mentioned a lot.

In the field of large scale infrastructure, there are needs for understanding the system wide behavior of a distributed system at runtime. This is at the heart of finding problems fast on hard to reproduce problems, including kernel, and apps crash and performance slowdowns.

Monitoring a system modify the system behavior and the measure itself, even in the computer domain. In the embedded and real-time, first there is the challenge to put an upper bound to tracing impact, to make sure to respect timing constraints, even in the case tracing is enabled.

Research

Sebastian Fischmeister from the University of Waterloo presented research about using a sampling approach to tracing for real-time systems. He presented an approach to add hardware instruction for tracing, that would run it only if the timing requirements would be met.

Ashvim Goel from the University of Toronto talked about increasing security by recording all system calls to allow off-line analysis. Data is indexed to allow fast queries.

Greg Frank from Carleton University presented performance model based on traces. Execution paths at the system level can be modeled by a graph. Graph can be annotated with resource consumption.

Del Mayers from the University of Victoria presented a reverse engineering tool using tracing. By running the program with the desired functionality, then repeating the scenario without using that particular activity, it's possible to do a difference set operation on called methods and isolate with low noise level the classes and methods that implements this particular functionality.

mercredi 23 février 2011

Managing Apache config with Augeas

Release 0.8.0 of Augeas includes a special lens for managing Apache web server configuration files. First, we will see how the lens maps sections and directives to the tree. Then, we will review some recepies to modify the configuration and show results.

Quick start

Apache configuration has two main components. The first component is section, which is similar to XML elements. Sections can be nested and contain directives. Directives are composed of a name and positional arguments.

As you may know, Apache is very modular. A module can define its own directives and Apache will run the module's callback to parse arguments. This is reflected in the way the configuration is handled in Augeas. The lens is mostly generic and allows arbitrary sections and directives, with arbitrary arguments. Apache allow case insensitive sections are directive. The actual version enforce that open and close tags to be the same case. I recommend to standardize the casing of the configuration for simplicity. Now, let's look at a small example, with one section and one directive.

<VirtualHost *:80>
  ServerAdmin foo@example.org
</VirtualHost>

This configuration produces the following tree.

{ "VirtualHost"
    { "arg" = "*:80" }
    { "directive" = "ServerAdmin"
      { "arg" = "foo@example.org" }
    }
  }

Let's say we want to modify the email address of the server admin, we can do a simple set:
augtool> set "/VirtualHost/*[self::directive='ServerAdmin']/arg" "bar@example.com"
To select the ServerAdmin directive, we need to search for it as a child of VirtualHost. We then set the first argument of the corresponding directive to a new value. Here is the resulting diff from the original file. If there are more than one VirtualHost entries in the file, then a simple set will fail, a set multiple (setm) is required to change them all at once.

$ diff -u httpd.conf httpd.conf.augnew 
--- httpd.conf 2011-02-22 22:03:34.000000000 -0500
+++ httpd.conf.augnew 2011-02-22 22:04:34.844099001 -0500
@@ -1,3 +1,3 @@
 <VirtualHost *:80>
-  ServerAdmin foo@example.org
+  ServerAdmin bar@example.org
 </VirtualHost>

Tree structure

There are 4 special things to know about the tree structure of apache configuration.

  • Section names are labels of the tree, they appear on the path.
  • Directives are held in value of a "directive" node.
  • Arguments of either sections or directives are held in values of "arg" node.
  • Arguments nodes must be before any other children.

To demonstrate this, let's create a configuration from scratch, and see it build at each step in augtool. First, launch augtool. I suggest to use the -n option to save to a new file.
$ sudo augtool -n
The variable $conf holds the path to the target empty file, for example under Ubuntu it would be:
augtool> defvar conf /files/etc/apache2/sites-available/foo

Step 1: create VirtualHost section

The clear command empty the value of a node and it create it if the node doesn't exists yet.
Command:
augtool> clear $conf/VirtualHost
Result:
<VirtualHost>
</VirtualHost>

Step 2: Set the argument of VirtualHost section.

Command:
augtool> set $conf/VirtualHost/arg "172.16.0.1:80"
Result:
<VirtualHost 172.16.0.1:80>
</VirtualHost>

Step 3: Create the ServerAdmin directive under VirtualHost.

Command:
augtool> set $conf/VirtualHost/directive "ServerAdmin"
Result:
<VirtualHost 172.16.0.1:80>
ServerAdmin
</VirtualHost>

Step 4: Set the ServerAdmin first argument to configure the email.

Command:
augtool> set $conf/VirtualHost/*[self::directive='ServerAdmin']/arg "baz@example.org"
Result:
<VirtualHost 172.16.0.1:80>
ServerAdmin baz@example.org
</VirtualHost>

The order matters

What if we perform step 3 before step 2? Here is the result:
augtool> set $conf/VirtualHost/directive "ServerAdmin"
augtool> set $conf/VirtualHost/arg "172.16.0.1:80"
augtool> print $conf
/files/etc/apache2/sites-available/foo
/files/etc/apache2/sites-available/foo/VirtualHost
/files/etc/apache2/sites-available/foo/VirtualHost/directive = "ServerAdmin"
/files/etc/apache2/sites-available/foo/VirtualHost/arg = "172.16.0.1:80"
augtool> save
Saving failed
augtool> print /augeas/files/etc/apache2/sites-available/foo/error/message = 

Failed to match ({ /arg/ = /[...]/ }({ /arg/ = /[...]/ })*)?(<<rec>>
| { /directive/ = /[...]/ } | { /#comment/ = /[...]/ } | { })*  

with tree

{ \"directive\" = \"ServerAdmin\" } { \"arg\" = \"172.16.0.1:80\" }"

I reformated the error message to highlight why it failed. The lens require "arg" nodes to appear before "directive", "#comment" and empty nodes. In this case, the node "directive" is before the "arg" node, and it doesn't match the tree structure. So, how to make sure that we insert nodes before any other? Here is the twist. First, we will remove the arg node and create it at the right place.

augtool> rm $conf/VirtualHost/arg
rm : $conf/VirtualHost/arg 1
augtool> ins arg before  $conf/VirtualHost/*[1]
augtool> set $conf/VirtualHost/arg "baz@example.org"
augtool> save
Saved 1 file(s)

And the corresponding result is the one expected. The predicate [1] will always select the first node in a node set and is equivalent to [position()=1]. There is one gotcha, that is if there are no children under VirtualHost, no node will match and the insert will fail. In this case, a simple set is required.

Also, take care to set a value to "arg" nodes! Otherwise, Augeas use the section name lens to render it. Here is the result of having an "arg" node with a null value.

<VirtualHost>
<arg>
</arg>
</VirtualHost>

Use cases

Modify document root

The first use case I show is to modify document root in the default configuration of Apache under Ubuntu. The default document root is "/var/www", but say we want to change it to "/srv/www". We have to modify the DocumentRoot directive and one Directory section. I'm using the match command to verify that the right node is selected before applying changes. (sorry for long lines...)

augtool> match $conf2/VirtualHost/*[self::directive="DocumentRoot"]
/files/etc/apache2/sites-available/default/VirtualHost/directive[2] = DocumentRoot
augtool> set $conf2/VirtualHost/*[self::directive="DocumentRoot"]/arg /srv/www
augtool> match $conf2/VirtualHost/Directory/arg[. = "/var/www/"]
/files/etc/apache2/sites-available/default/VirtualHost/Directory[2]/arg = /var/www/
augtool> set $conf2/VirtualHost/Directory/arg[. = "/var/www/"] "/srv/www/"
augtoo> save
Saved 1 file(s)

Here is the resulting diff.

--- /etc/apache2/sites-available/default 2011-02-22 23:30:48.000000000 -0500
+++ /etc/apache2/sites-available/default.augnew 2011-02-22 23:48:10.000000000 -0500
@@ -1,12 +1,12 @@
 
  ServerAdmin webmaster@localhost
 
- DocumentRoot /var/www
+ DocumentRoot /srv/www
  <Directory>
   Options FollowSymLinks
   AllowOverride None
  </Directory>
- <Directory /var/www/>
+ <Directory /srv/www/>
   Options Indexes FollowSymLinks MultiViews
   AllowOverride None
   Order allow,deny

Changing permissions


On Ubuntu, Apache is configured to serve documentation on http://localhost/doc/. We will share this documentation with everybody by changing Order and Allow from directive and delete Deny directive of the doc directory. We are using the regexp function to select the node with or without leading slash and with or without quotes. We remove all arguments of "Allow from" to make sure that arguments are sane.

augtool> match $conf2/VirtualHost/Directory[arg =~ regexp(".*/usr/share/doc.*")]/
/files/etc/apache2/sites-available/default/VirtualHost/Directory[4] = (none)
augtool> defvar dir $conf2/VirtualHost/Directory[arg =~ regexp(".*/usr/share/doc.*")]/
augtool> rm $dir/*[self::directive="Allow"]/arg
augtool> set $dir/*[self::directive="Allow"]/arg[1] from
augtool> set $dir/*[self::directive="Allow"]/arg[2] all
augtool> set $dir/*[self::directive="Order"]/arg[1] "allow,deny"
augtool> rm $dir/*[self::directive="Deny"]
rm : $dir/*[self::directive="Deny"] 3
augtool> save
Saved 1 file(s)

In this example, the predicate "*[self::directive='Allow']" can be rewritten "directive[ . = 'Allow']", both are equivalent.

Here is the resulting diff.
--- /etc/apache2/sites-available/default 2011-02-22 23:30:48.000000000 -0500
+++ /etc/apache2/sites-available/default.augnew 2011-02-23 00:10:14.000000000 -0500
@@ -33,9 +33,8 @@
     <Directory "/usr/share/doc">
         Options Indexes MultiViews FollowSymLinks
         AllowOverride None
-        Order deny,allow
-        Deny from all
-        Allow from 127.0.0.0/255.0.0.0 ::1/128
+        Order allow,deny
+        Allow from all
     </directory>

Conclusion

Augeas is a very powerful and precise tool to modify Apache configuration file. We can do about any changes with a very simple tree structure. As always, don't forget to reload Apache configuration for changes to take effect.

Thanks to David Lutterkort, who designed the amazing recursive lens that Apache lens uses and feedback for the square lens, and Raphaël Pinson for the feedback and stress test of the lens on more than 2000 Apache configurations and the help for this blog post.

Happy hacking!

jeudi 27 janvier 2011

Visiting Event Tracing for Windows

In previous posts, we discussed Linux kernel tracing with LTTng. On the Microsoft side, Event Tracing for Windows allows to gather a kernel trace and user space trace. It's advertised as low-impact, lock-less, per-cpu buffers tracer, with live mode and circular buffers option. Quite interesting.
Here is a quick introduction to how to gather a simple trace on Windows 7 Professional and the different analysis we can get.

Installation

Obviously, you will need a Windows 7 Professional host. I installed it in a Linux KVM virtual machine, with 20GB of storage and with two CPUs emulated, with all default options.
First, .NET framework 4 has to be installed, required to install tracing tools bundled with Windows SDK.
In summary, you need to install:
  • dotNetFx40_Full_x86_x64
  • winsdk_web
It will install required tools for tracing: xperf, xperfview, tracelog and tracerpt.

Get a trace

To start tracing, open a console in administration mode, as shown in the following screen shot.


We create a trace directory for our experiments, and start and stop a simple trace with tracelog, as shown in the following screen shot. While tracing, you can start programs to create some activity on the system. I started IE and did some random browsing.

The trace file output is set with "-f" option. If a lot of events occurs, some events can be lost. If such a thing occur, increase the buffers size with "-b" option. Other options are there for some extra trace events, refer to help for more information. To give an idea of the disk requirement, I got a trace of about 20MB for a minute of tracing under light load. The trace file can hence become very big.


If the user doesn't have enough privileges for tracing, the following error message will be raised. Make sure the console is launched as administrator.

C:\trace>tracelog -f kernel.etl -start
Setting log file to: C:\trace\kernel.etl
Could not start logger: NT Kernel Logger
Operation Status: 5L
Access is denied.



Analyze the trace

Launch xperfview to start the Windows Performance Analyzer. Then, load the trace kernel.etl obtained previously. Here is what it looks like.
Disk access graph and CPU usage according to time and process in xperfview.

Process life graph and page faults by process according to time in xperfview.
Offset of disk access to detect system-wide bad seek behavior.

Summary of events count obtained from tracerpt
What I like about xperf is the ability to isolate resource usage per process. Also, zooming in a trace is intuitive by selecting with the mouse an interval that seems interesting. Trace events are completely abstracted as chart and statistics. There views are appropriate for understanding overall system performance. Also, when executable symbols are loaded, the call trace performance is available, which may be very handy for the software optimization. 
The tracerpt utility outputs reports from a trace file, one is the count of all events and the report in HTML gives the statistics for the whole trace by subsystem. Here is an example of report.html generated with tracerpt.

vendredi 7 janvier 2011

Tracing a linux cluster

Gather traces from multiple machines and then showing them all at once is a real challenge, because each computer has it's own independent clock. It means that two events occurring at the same time on two computers have a low probability to have the same time stamp in the trace.

Linux Trace Toolkit have a synchronization feature to adjust trace time stamps to a reference trace. It works by matching sent and received network packets found in traces. Two parameters are computed: an offset, but also a drift, that is the rate of clock change.

To experiment it, I did a virtual Ubuntu cluster of 10 nodes installed with LTTng. Virtual machines are sending each other TCP packets with the small utility pingpong while tracing is enabled. All traces are then sync to the host for analysis. Here are the results:

$ lttv -m sync_chain_batch --sync --sync-stats -t trace1 -t trace2 [...]
[...]
Resulting synchronization factors:
 trace 0 drift= 1 offset= 6.80407e+09 (2.551684) start time= 2433.182802117
 trace 1 drift= 1 offset= 4.12691e+09 (1.547687) start time= 2433.254700670
 trace 2 drift= 0.999999 offset= 0 (0.000000) start time= 2433.229372444
 trace 3 drift= 1 offset= 1.53079e+09 (0.574083) start time= 2433.366687088
 trace 4 drift= 1 offset= 2.31812e+10 (8.693471) start time= 2433.217954184
 trace 5 drift= 1 offset= 1.48957e+10 (5.586227) start time= 2433.280525047
 trace 6 drift= 1 offset= 1.76688e+10 (6.626211) start time= 2433.291125350
 trace 7 drift= 1 offset= 2.0463e+10 (7.674116) start time= 2433.325424020
 trace 8 drift= 0.999999 offset= 1.2206e+10 (4.577534) start time= 2433.204361289
 trace 9 drift= 1 offset= 9.55947e+09 (3.585022) start time= 2433.293578996
[...]

The trace 2 has been selected as the reference trace. We see inside parenthesis the offset between the current trace and the reference trace. We see a delay between each trace that match the delay between virtual machines startup. When loading these traces into lttv with --sync option, all traces events align perfectly, which is not the case without the sync option.

If you want to know more about trace synchronization, I recommend the paper Accurate Offline Synchronization of Distributed Traces Using Kernel-Level Events from Benjamin Poirier.

One simple note if you want to do this analysis, you need extended network trace events. To enable them, arm ltt with

$ sudo ltt-armall -n

I found it really interesting, because it allows to see cluster-wide system state.

jeudi 9 décembre 2010

CPU history from kernel trace

Everybody is familiar with CPU history usage, for example with GNOME monitor. We see the average usage in time.


The GNOME monitor poll /proc/stats at regular interval to compute average usage. This file is updated by the kernel. The values comes from sampling that the kernel does for accounting various process.

How could we compute the CPU usage history from the actual kernel trace? We only have to look at sched_schedule events. The event inform us that in a certain point in time, the kernel switched the task on a given CPU. If the new task has PID zero, we know that's the idle thread from the kernel. By splitting running and idle time in fixed intervals, we can compute CPU average usage.

I show one small examples done on my computer that is dual core. First, we see the execution of three cpuburn process started with one second of delay. We can see the result in the control flow viewer in LTTV, and the resulting CPU usage view.



We see a peek at the beginning of the trace. This is likely to be related to the metadata flushing when a trace is started. The two steps after are related to each cpuburn process, and we see that when the third process is started, the CPU usage stays at 100%.

For testing, I added scripts to generate those traces automatically on your computer. It's written in Java, and you will need some extra packages to run it, see the README file. Get the code on github:

https://github.com/giraldeau/flightbox

Happy hacking!

vendredi 12 novembre 2010

Introduction to Linux Tracing Toolkit

The Linux Tracing Toolkit next generation (LTTng) is absolutely amazing. In this introduction, we will look at how to interpret the kernel trace of a small program by comparing it to strace. If you want to install components and get a trace on your own machine, you can get packages for the patched kernel and other tools for Ubuntu Maverick in LTTng's PPA on Launchpad. You will also need build-essential to compile the small C executable, strace and hexdump.

Here is the small program. It opens a file and write a integer into it. Then, it adds number in a for loop.
#include <stdio.h>
#define INT_MAX 2147483647
int main(volatile int argc, char **argv) {
    int i = 3;
    FILE *fd = fopen("test.out", "w");
    fwrite(&i, sizeof(int), 1, fd);
    fclose(fd);
    volatile long a;
    int x;
    for (x = 0; x<INT_MAX; x++) {
        a++;
    }
    return 0;
}

Compile it, test it and run it under strace:
$ gcc -o usecase usecase.c
$ ./usecase
$ strace -o usecase.strace ./usecase
Ok. Now, let's run the program under tracing, but before, we have to enable all trace points in the kernel.
$ sudo ltt-armall
To get a tight window around the command, I'm using the small script trace-cmd.sh (see at the end of the post). The script simply starts tracing, run the program and stop the trace. Invoke it like this (don't forget to set the script executable):
./trace-cmd.sh ./usecase
Now, we are ready to launch lttv-gui, which is the utility to look at the trace. To load a trace, select File->Add trace, then select the "trace-cmd" directory created in the same directory as the trace-cmd.sh script. Then, scroll down to the "./usecase" process in the control flow viewer, which is in the middle of the window. Each trace events are displayed under the graph. I will present three phase of the process. First, the creation and file access, then computation phase and the process exit. Trace is rotated to make it more readable. Events name and comments are embedded in the graph. strace events are in red, while related code is in blue.



In addition to system calls, we can look at the paging of an application and see process starvation. This information is not shown by strace. Another cool side effect is that, contrary to strace, the running program can't detect it's under tracing, then we can trace viruses that otherwise quit before they can be analyzed. Tracing reports much more information about kernel internals, which helps a lot to understand what's going on. Events timestamps of the kernel trace are in nanoseconds, so the precision is really high, and since trace points are static (simple function calls compiled right into the kernel), performance impact is ridiculously low, below 3% for core trace points! I'm running LTTng in background on my system without noticeable impact, in flight recorder mode.

I will be working on advanced trace analysis for the next three years or so for my PhD. Since LTTng got all the feature I need for tracing, I will use this tools. My first goal is to create a CPU usage view. Say that something was eating your CPU a minute ago, then with kernel tracing you would be able to go in the "flight recorder" history and see what was running at that time, and understand what was going on.

You can help me in two ways. First, by submitting your ideas about cool trace analysis we could perform and/or you need. Second, you can write to Linus Torvalds and ask him to merge LTTng in mainline. LTTng is the right stuff we need for tracing and it's a bit a shame that this not merged yet while other operating systems have this since a decade.

Next post will be about TMF, an eclipse plugin for trace analysis! Stay tuned!

Script trace-cmd.sh:
#!/bin/sh

if [ -z "$@" ]; then
    echo "missing command argument"
    exit 1
fi

cmd="$@"

name="cmd"
dir="$(pwd)/trace-$name"
sudo rm -rf $dir
sudo lttctl -o channel.all.bufnum=8 -C -w $dir $name
echo "executing $cmd..."
$cmd
echo "return code: $?" 
sudo lttctl -D $name

vendredi 22 octobre 2010

Scary pumpkin

I left my computer for few minutes to carve the scariest pumpking for any programmer, the Big O factorial time pumpkin!

Terrifying, isn't?! Hand carved into a local organic grown pumpkin, low power lightening with LEDs, eatable after use, I'm ready for an happy hacking halloween!