Tuesday Jun 07, 2005

On Gaming (part 2)

A screenshot showing quake2 running under Solaris x86/amd64 using OpenGL and the nVidia Solaris drivers :-)

Oh and to link back to my ongoing dtrace obsession, the top left corner shows counts every 5 secs of the quake2 functions being called. A dtrace one liner:

        dtrace -n 'pid1057:a.out::entry{@c[probefunc] = count();} tick-5sec{printa(@c); trunc(@c,1);}'
Will be trying out some other OpenGL based things as time goes on...

Thursday May 12, 2005

More Beer !

Somewhat inspiried by the python beer.py script, and more so by Brendan Gregg's dtrace'd Guessing Game, heres some beer thanks to dtrace.

#!/usr/sbin/dtrace -s

        n = 10;
        ifor = 1;

/!n && !ifor/
        printf("no more bottles of beer on the wall");

/n == 1 && !ifor/
        printf("one more bottle of beer on the wall");
        ifor = 1;

/n > 1 && !ifor/
        printf("%d bottles of beer on the wall", n);
        ifor = 1;

        ifor = 0;

Dtrace can't do loops (for good reason), but this script shows an example of getting something similar out of it..

# dtrace -s beer.d   
dtrace: script 'beer.d' matched 5 probes
CPU     ID                    FUNCTION:NAME
  0  39815                       :tick-1sec 9 bottles of beer on the wall
  0  39815                       :tick-1sec 8 bottles of beer on the wall
  0  39815                       :tick-1sec 7 bottles of beer on the wall
  0  39815                       :tick-1sec 6 bottles of beer on the wall
  0  39815                       :tick-1sec 5 bottles of beer on the wall
  0  39815                       :tick-1sec 4 bottles of beer on the wall
  0  39815                       :tick-1sec 3 bottles of beer on the wall
  0  39815                       :tick-1sec 2 bottles of beer on the wall
  0  39815                       :tick-1sec one more bottle of beer on the wall
  0  39815                       :tick-1sec no more bottles of beer on the wall


Tuesday May 10, 2005

Beer, python and stuff

Question asked on the dtrace forums about adding dtrace probes to python. Following Bart's example and the docs, heres YAE (Yet Another Example) on adding dtrace functionality to an application.

This really is probably an example of where one shouldn't really use dtrace. See down at the end why.

First off, what do we want to look at from the application that dtrace can't already give us ? Well python is an interpeted language(?) so lets try and show what functions from a python script are being called. (this can already be done without modifying python's source code, though I'm too lazy to go figuring out the PyObject\* structures, this is easier or is it right?).

Quickly browsing the code, looks like theres the fast_function function that can call script functions. Seems like as good as place as any to place a dtrace probe. The source file is Python/ceval.c. Adding a simple probe at the start of this to have the line number and script function name:

PyObject \*
fast_function(PyObject \*func, PyObject \*\*\*pp_stack, int n, int na, int nk)
        PyCodeObject \*co = (PyCodeObject \*)PyFunction_GET_CODE(func);
        PyObject \*globals = PyFunction_GET_GLOBALS(func);
        PyObject \*argdefs = PyFunction_GET_DEFAULTS(func);
        PyObject \*\*d = NULL;
        int nd = 0;

        DTRACE_PROBE2(python, pythond__2,
                co->co_firstlineno, PyString_AS_STRING(co->co_name));

Then create the dtrace provider script, Python/pythond.d:

provider python {
        probe pythond__2(int, string);
Thats all. A few tweaks to the Makefile for compiling the dtrace script like:
Python/pythond.o: $(srcdir)/Python/pythond.d $(PYTHON_OBJS) $(OBJECT_OBJS)
        /usr/sbin/dtrace -G -32 -o $@ -s $(srcdir)/Python/pythond.d $(PYTHON_OBJS)
Compile it up and give it a roll.
Python-2.4.1/Demo/scripts# dtrace  -n 'python$target:::pythond-2' -c '../../python beer.py 1 '
dtrace: description 'python$target:::pythond-2' matched 1 probe
one bottle of beer on the wall,
one bottle of beer.
Take one down, pass it around,
no more bottles of beer on the wall.
dtrace: pid 1158 has exited
CPU     ID                    FUNCTION:NAME
  0  37700          fast_function:pythond-2
Right, the probe gets fired, a lot. Probably cause I haven't installed and compiled all the installable python scripts into python bytecode.

Lets see what I'm calling.

Python-2.4.1/Demo/scripts# dtrace -o beer.out -n 'python$target:::pythond-2{@[stringof(copyinstr(arg1)), arg0]=count();}' -c '../../python beer.py 200' > /dev/null
dtrace: description 'python$target:::pythond-2' matched 1 probe
dtrace: pid 1172 has exited
Looking through the output file, beer.out, I see the script function 'bottle' being called 600 times from line number 6:
  getwidth                                                        140               15
  fixup                                                            46               22
  isident                                                         210               25
  match                                                           195               53
  get                                                             201              283
  __next                                                          182              313
  bottle                                                            6              600
Sure enough the script function, bottle, is at line number 6. Similarly the script function, match, is at line 195 from the file Lib/sre_parse.py.
Python-2.4.1$ grep -n 'def match(' Lib/\*.py | grep '\^195'
sre_parse.py:195:    def match(self, char, skip=1):
Python-2.4.1$ grep -n bottle Demo/scripts/beer.py | grep '\^6:'
6:def bottle(n):
This is cool, I could now go and find hotspots in any python script I have. Those who know the python code better could add in a probe for python bytecode scripts as well. I know there are the settrace and setprofile functions in python, but they're thread specific and could be cumbersome to use on a live system (or thats what I read from the python docs).

I need to do something like this for perl and shell.

A quick addition to the provider to be able to print the file of the script function gets me:

# dtrace -o d1 -n 'python$target:::pythond-2{@[stringof(copyinstr(arg1)), stringof(copyinstr(arg2))]=count();}' -c '../pythonscripts/beer.py 300' 
  match         Python-2.4.1/Lib/sre_parse.py               53
  get           Python-2.4.1/Lib/sre_parse.py              283
  __next        Python-2.4.1/Lib/sre_parse.py              313
  bottle        scripts/beer.py                            900
So the bottle function from the file scripts/beer.py was called 900 times.

Ok, why you shouldn't really use dtrace here like this. All the info gathered here is passed to fast_function() within the first argument. Having a simpler dtrace script to delve into this structure to pull out the info is all thats needed. Something like:

#!/usr/sbin/dtrace -s

#include "Python.h"

#include "compile.h"
#include "frameobject.h"
#include "eval.h"
#include "opcode.h"
#include "structmember.h"

PyCodeObject \*co;

        co = (PyCodeObject \*)PyFunction_GET_CODE(arg0);
        printf("python: %d %s %s\\n",
This means having some of the python source code somewhere whenever this script is run. Or pull out the structs into the script it self. Fun and games.

Friday Feb 11, 2005

With Samba

Solaris 10 comes bundled with a good deal of free software; bash, apache, gtar, gnome as well as samba the windows fileserver for unix. An idea came up on the samba-tech interest list here. One had the nice idea of building a "performance auditor module" for samba. This module would collect data about say the number of times a samba vfs call is made and perhaps the average time the call took.

While this module can be written for samba, I'd imagine it as another vfsmodule, the data can already be collected without any a single new line of samba code being written. Yeilding something like:

Counts of each function:
  vfswrap_dummy_connect                                             1
  vfswrap_dummy_disconnect                                          1
  vfswrap_chdir                                                     2
  vfs_ChDir                                                         3
Average times spent in each function:
  vfswrap_dummy_disconnect                                       7192
  vfs_ChDir                                                     11772
  vfswrap_chdir                                                 32179
  vfswrap_dummy_connect                                        288427
Times are in nanoseconds, so divide by 1000000000 to get things into more human readable numbers. And heres the dtrace script
        self->start = timestamp;
        @counts[probefunc] = count();

        this->elapsed = timestamp - self->start;
        self->start = 0;
        @avg_times[probefunc] = avg(this->elapsed);
Within Sun we're using dtrace like this on an on-going basis. Build one version of a piece of software, benchmark it with dtrace, build a newer version, benchmark it with dtrace again and note any differences which can show any regressions (if any).

Wednesday Jan 26, 2005

Absent leaves

Finally getting to add an entry. Solaris being an ongoing development I've lost time to update this blog. Making some time for this will be my new endeavor (hopefully).

With that I ran into (and solved with dtrace) a little problem here. Wanting to see if a particular program was calling a particular libc(3LIB) function, setlocale(2) as it happened. We could use apptrace(1) but the program was being run from within a suite of software and this suite wasn't easy (or we were unwilling) to change it to use apptrace(1). Using dtrace to find if a process is calling a particular funcion is dead easy;

# dtrace -n 'pid$target::read:entry{}' -p 15250
dtrace: description 'pid$target::read:entry' matched 4 probes
CPU     ID                    FUNCTION:NAME
  1  46195                       read:entry 
But what of when a process would load a library after dtrace is tracing it ? This came up in the dtrace forum on this thread. Bryan, of course, came up with an answer. That and with Morgan Herrington's help, aka script-reuse, the following three dtrace scripts were written. The first, master.d, would watch for the invocation of a particular program. It would then stop the program via the dtrace function, stop() and also fork off the second dtrace script, mon_pre.d. This second dtrace script then starts the program again via prun, but stops it when the program enters main(). Finally it would fork off the last dtrace script, mon.d. Finally the third and last dtrace script would watch for particular functions being called.


#!/usr/sbin/dtrace -s

#pragma D option destructive

/execname == $$1/

        printf("%d %s\\n", pid, execname);
        printf("forking pre-monitor to watch ...%s\\n\\n", $$1);
        printf("./mon_pre.d %d &\\n\\n", pid);

        system("./mon_pre.d %d &", pid); 
#!/usr/sbin/dtrace -Fs

#pragma D option destructive

        printf("pruning process %d \\n", $1);
        system("prun %d", $1);

        printf("forking final monitor to watch %d\\n\\n", $1);
        system("./mon.d %d &", pid);
and finally mon.d
#!/usr/sbin/dtrace -Fs

#pragma D option destructive

        printf("pruning %d process\\n", $1);
        system("prun %d", $1);

        @[probefunc] = count();

One thing these scripts show is the use of the destructive mode of dtrace. Which should be used very very carefully lest one hangs ones system or worse. Credit is due to Morgan who wrote these scripts. Thanks Morgan !



« July 2016