Implement LD_PRELOAD library to log IO for profiling

[Richard Boulton]

It would be good to have a way to get a log of all the IO performed by Xapian during indexing or search, so that we can profile it.

Attached is a patch to xapian which does just this - it's controlled by setting the XAPIAN_IO_LOG env var to a filename to store the log in (optionally with %p replaced with the process ID). The output format is fairly easy to parse: one line for each operation, with the first character indicating the operation type, followed by the filedescriptor involved, followed by the start time (as in integer, in microseconds since epoch), followed by the elapsed time, followed by the filename for open, or the offset and length for read or write.

It might be better to use an LD_PRELOAD hack, or some other tracing technique, to get these log files, but the patch is a simple way to get them for now.

I've put a script into xapian-maintainer-tools/perftest/ which displays the generated logs graphically (it takes a while to draw for large log files).

[Richard Boulton]

Initial patch to implement this logging.

[Olly Betts]

perl script to analyse strace output

[Olly Betts]

The attached script analyses output from strace to produce a list of blocks read from database tables.

It tracks the filename associated with each fd (or at least with those which matter here) so it can report which database and table the block was read from.

I think overall this is a better approach than adding logging calls to our code:

• explicit logging calls may not get added everywhere - strace can't miss a call

• strace should be lower overhead, at least if you tell it which syscalls are interesting with something like: strace -e trace=open,pread,close,dup,dup2,dup3

• no need to recompile xapian-core to get the IO log (or carry the overhead of the logging when you don't need it)

The drawback is strace isn't as portable - strace 4.7 actually dropped support for non-Linux platforms. My thought is that an LD_PRELOAD wrapper is a good approach for other platforms - LD_PRELOAD or equivalent is available fairly widely.

I've not tried to make this a drop-in replacement compatible with the log format from the patch here, but that shouldn't be hard to do if the visualisation tool is worth keeping. You can get strace to log the time of each call to the nearest microsecond using strace -ttt).

[Olly Betts]

Let's sort out tidying this stuff up and including it somewhere useful (maybe in releases, maybe just somewhere in the repo).

[Olly Betts]

Added the attached script in [1618310].

[Olly Betts]

I hacked up the script to produce a compatible log format, but the visualisation doesn't actually seem very useful - I'll attach that patch (which doesn't currently work with strace -y but would be easy to tweak to do so).

So we now have addressed this for Linux at least, and perhaps for some other platforms if strace worked well enough there before it went Linux-only.

Retitling to make this about adding an LD_PRELOAD library to handle other platforms, and moving to 1.3.x milestone, since we have at least addressed this on the platform where Xapian is probably most widely developed and used.

[Olly Betts]

Patch to produce log compatible with draw_positions.py

[Olly Betts]

Not a blocker for 1.4.0.

[Olly Betts]

[3c3c09048e134a82c7e0e16eee0dfc71e2eb6615] implements this and works for x86-64 Linux. It needs some work on portability (I think we probably need a configure script to detect things like whether we need to use off64_t in pread64() and pwrite64()).

Tanmay also pointed out elsewhere that a dtrace script could log the required data (and quite a lot of platforms have dtrace support).

[Olly Betts]

I've added a simple automated test for xapian-io-profile in 54779bea85b25d84f61e35a30320699582ea5ef1 which checks that all the expected functions are intercepted and logged, and that 64-bit offsets work.

Currently this passes on x86-64 Linux but fails on x86 Linux. I'll work to fix it there and then I think we can close this. Interested developers on other platforms can check if it works by running make check (and try to fix it if it doesn't!)

Logging using dtrace is potentially interesting, but it's not packaged for Debian at least (maybe due to the CDDL licence?) so I'll also leave that for interested developers on other platforms. On Linux we already have a choice of strace or xapian-io-profile, and while dtrace (or the Linux-specific EBPF) is likely a lower overhead option the overhead shouldn't be a big concern with the events we're logging.

[Olly Betts]

I've added a simple autotools build system in cb2f5ab88fb18504b485bec73fcae07d64721740.

eea4e7b6f546dc7561900e3849253662cb09f143 makes things work properly on x86 Linux (as well as x86-64 Linux).

I expect this should now work on any Linux architecture.