Event와 tracepoint를 이용한 동작 분석 참고 사항

분석 범위와 사용 가능한 event 찾기

저자는 Mel Gorman이며 PCL 관련 내용은 Ingo Molnar의 email에 크게 기반합니다. tracepoint는 custom kernel module과 probe function을 따로 만들지 않고 event tracing infrastructure를 통해 사용할 수 있습니다. 자세한 정의는 `Documentation/trace/tracepoints.rst`를 참조합니다.

간단히 말해 tracepoint는 system 안에서 벌어지는 일을 여러 event와 결합해 큰 그림으로 구성할 수 있는 중요한 지점을 나타냅니다. event를 수집하고 해석하는 방법은 많지만 당시 정립된 best practice가 없어, 이 문서는 사용할 수 있는 몇 가지 방법을 소개합니다.

문서는 debugfs가 `/sys/kernel/debug`에 mount되어 있고 kernel에 적절한 tracing option이 구성됐다고 가정합니다. 또한 PCL 도구인 `tools/perf`가 설치되어 PATH에서 실행 가능하다고 가정합니다.

모든 가능한 event는 `/sys/kernel/tracing/events`에서 볼 수 있습니다. `find`로 directory를 나열하면 사용할 수 있는 event 수를 대략 파악할 수 있습니다.

$ find /sys/kernel/tracing/events -type d

`perf`는 tracepoint를 포함한 모든 counter와 event를 탐색하고 열거할 수 있습니다. `perf list` 결과에서 `Tracepoint`를 찾으면 ext4 예제처럼 event 이름과 종류가 표시됩니다.

  $ perf list 2>&1 | grep Tracepoint
  ext4:ext4_free_inode                     [Tracepoint event]
  ext4:ext4_request_inode                  [Tracepoint event]
  ext4:ext4_allocate_inode                 [Tracepoint event]
  ext4:ext4_write_begin                    [Tracepoint event]
  ext4:ext4_ordered_write_end              [Tracepoint event]
  [ .... remaining output snipped .... ]

=========================================================
Notes on Analysing Behaviour Using Events and Tracepoints
=========================================================
:Author: Mel Gorman (PCL information heavily based on email from Ingo Molnar)

1. Introduction
===============

Tracepoints (see Documentation/trace/tracepoints.rst) can be used without
creating custom kernel modules to register probe functions using the event
tracing infrastructure.

Simplistically, tracepoints represent important events that can be
taken in conjunction with other tracepoints to build a "Big Picture" of
what is going on within the system. There are a large number of methods for
gathering and interpreting these events. Lacking any current Best Practises,
this document describes some of the methods that can be used.

This document assumes that debugfs is mounted on /sys/kernel/debug and that
the appropriate tracing options have been configured into the kernel. It is
assumed that the PCL tool tools/perf has been installed and is in your path.

2. Listing Available Events
===========================

2.1 Standard Utilities
----------------------

All possible events are visible from /sys/kernel/tracing/events. Simply
calling::

  $ find /sys/kernel/tracing/events -type d

will give a fair indication of the number of events available.

2.2 PCL (Performance Counters for Linux)
----------------------------------------

Discovery and enumeration of all counters and events, including tracepoints,
are available with the perf tool. Getting a list of available events is a
simple case of::

  $ perf list 2>&1 | grep Tracepoint
  ext4:ext4_free_inode                     [Tracepoint event]
  ext4:ext4_request_inode                  [Tracepoint event]
  ext4:ext4_allocate_inode                 [Tracepoint event]
  ext4:ext4_write_begin                    [Tracepoint event]
  ext4:ext4_ordered_write_end              [Tracepoint event]
  [ .... remaining output snipped .... ]

system-wide event 활성화

system-wide event 활성화의 전체 설명은 `Documentation/trace/events.rst`에 있습니다. 아래 shell loop는 이름에 `mm_`가 들어간 enable file을 찾아 1을 써 page allocation 관련 event를 모두 켭니다.

$ for i in `find /sys/kernel/tracing/events -name "enable" | grep mm_`; do echo 1 > $i; done

SystemTap에서는 `kernel.trace()` function으로 tracepoint에 접근합니다. 예제는 `mm_page_alloc` event마다 실행 process 이름별 page allocation 횟수를 누적하고 5초마다 출력한 뒤 map을 비웁니다.

  global page_allocs

  probe kernel.trace("mm_page_alloc") {
  	page_allocs[execname()]++
  }

  function print_count() {
  	printf ("%-25s %-s\n", "#Pages Allocated", "Process Name")
  	foreach (proc in page_allocs-)
  		printf("%-25d %s\n", page_allocs[proc], proc)
  	printf ("\n")
  	delete page_allocs
  }

  probe timer.s(5) {
          print_count()
  }

PCL에서는 `-a` switch와 `sleep`을 함께 사용해 일정 시간 동안 system-wide event를 셀 수 있습니다. 예제는 10초 동안 page allocation과 두 종류의 free event를 집계합니다.

 $ perf stat -a \
	-e kmem:mm_page_alloc -e kmem:mm_page_free \
	-e kmem:mm_page_free_batched \
	sleep 10
 Performance counter stats for 'sleep 10':

           9630  kmem:mm_page_alloc
           2143  kmem:mm_page_free
           7424  kmem:mm_page_free_batched

   10.002577764  seconds time elapsed

같은 방식으로 shell을 실행하고 원하는 시점에 종료하면 그때까지의 report를 얻을 수 있습니다.

3. Enabling Events
==================

3.1 System-Wide Event Enabling
------------------------------

See Documentation/trace/events.rst for a proper description on how events
can be enabled system-wide. A short example of enabling all events related
to page allocation would look something like::

  $ for i in `find /sys/kernel/tracing/events -name "enable" | grep mm_`; do echo 1 > $i; done

3.2 System-Wide Event Enabling with SystemTap
---------------------------------------------

In SystemTap, tracepoints are accessible using the kernel.trace() function
call. The following is an example that reports every 5 seconds what processes
were allocating the pages.
::

  global page_allocs

  probe kernel.trace("mm_page_alloc") {
  	page_allocs[execname()]++
  }

  function print_count() {
  	printf ("%-25s %-s\n", "#Pages Allocated", "Process Name")
  	foreach (proc in page_allocs-)
  		printf("%-25d %s\n", page_allocs[proc], proc)
  	printf ("\n")
  	delete page_allocs
  }

  probe timer.s(5) {
          print_count()
  }

3.3 System-Wide Event Enabling with PCL
---------------------------------------

By specifying the -a switch and analysing sleep, the system-wide events
for a duration of time can be examined.
::

 $ perf stat -a \
	-e kmem:mm_page_alloc -e kmem:mm_page_free \
	-e kmem:mm_page_free_batched \
	sleep 10
 Performance counter stats for 'sleep 10':

           9630  kmem:mm_page_alloc
           2143  kmem:mm_page_free
           7424  kmem:mm_page_free_batched

   10.002577764  seconds time elapsed

Similarly, one could execute a shell and exit it as desired to get a report
at that point.

process-local event와 filtering

thread별 event 활성화는 `Documentation/trace/ftrace.rst`의 `set_ftrace_pid` 설명을 따릅니다.

PCL에서는 process 실행 시간 동안 local event를 활성화하고 추적할 수 있습니다. 예제는 `./hackbench 10` 실행 동안 page allocation과 free event를 세고 실행 시간과 counter를 출력합니다.

  $ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free \
		 -e kmem:mm_page_free_batched ./hackbench 10
  Time: 0.909

    Performance counter stats for './hackbench 10':

          17803  kmem:mm_page_alloc
          12398  kmem:mm_page_free
           4827  kmem:mm_page_free_batched

    0.973913387  seconds time elapsed

event filtering은 `Documentation/trace/ftrace.rst`가 자세히 다룹니다. `trace_pipe`를 `grep`·`awk`로 거르거나 trace_pipe를 읽는 script에서 filtering하는 방법도 사용할 수 있습니다.

3.4 Local Event Enabling
------------------------

Documentation/trace/ftrace.rst describes how to enable events on a per-thread
basis using set_ftrace_pid.

3.5 Local Event Enablement with PCL
-----------------------------------

Events can be activated and tracked for the duration of a process on a local
basis using PCL such as follows.
::

  $ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free \
		 -e kmem:mm_page_free_batched ./hackbench 10
  Time: 0.909

    Performance counter stats for './hackbench 10':

          17803  kmem:mm_page_alloc
          12398  kmem:mm_page_free
           4827  kmem:mm_page_free_batched

    0.973913387  seconds time elapsed

4. Event Filtering
==================

Documentation/trace/ftrace.rst covers in-depth how to filter events in
ftrace.  Obviously using grep and awk of trace_pipe is an option as well
as any script reading trace_pipe.

반복 측정과 event 변동성

workload 결과는 실행마다 달라질 수 있으므로 standard deviation을 아는 것이 중요합니다. 보통 performance analyst가 직접 계산하지만 discrete event 발생 횟수가 유용하다면 `perf stat --repeat`를 사용할 수 있습니다.

첫 예제는 hackbench를 5회 실행하고 각 page event와 elapsed time의 평균 및 `+-` 백분율 변동을 보여 줍니다.

  $ perf stat --repeat 5 -e kmem:mm_page_alloc -e kmem:mm_page_free
			-e kmem:mm_page_free_batched ./hackbench 10
  Time: 0.890
  Time: 0.895
  Time: 0.915
  Time: 1.001
  Time: 0.899

   Performance counter stats for './hackbench 10' (5 runs):

          16630  kmem:mm_page_alloc         ( +-   3.542% )
          11486  kmem:mm_page_free	    ( +-   4.771% )
           4730  kmem:mm_page_free_batched  ( +-   2.325% )

    0.982653002  seconds time elapsed   ( +-   1.448% )

여러 discrete event를 집계해야만 얻을 수 있는 higher-level event가 필요하다면 별도 script를 개발해야 합니다.

`--repeat`에 `-a`와 `sleep`을 결합하면 system-wide event가 시간에 따라 얼마나 변하는지도 볼 수 있습니다. 둘째 예제는 1초 구간을 10회 반복합니다.

  $ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free \
		-e kmem:mm_page_free_batched \
		-a --repeat 10 \
		sleep 1
  Performance counter stats for 'sleep 1' (10 runs):

           1066  kmem:mm_page_alloc         ( +-  26.148% )
            182  kmem:mm_page_free          ( +-   5.464% )
            890  kmem:mm_page_free_batched  ( +-  30.079% )

    1.002251757  seconds time elapsed   ( +-   0.005% )

5. Analysing Event Variances with PCL
=====================================

Any workload can exhibit variances between runs and it can be important
to know what the standard deviation is. By and large, this is left to the
performance analyst to do it by hand. In the event that the discrete event
occurrences are useful to the performance analyst, then perf can be used.
::

  $ perf stat --repeat 5 -e kmem:mm_page_alloc -e kmem:mm_page_free
			-e kmem:mm_page_free_batched ./hackbench 10
  Time: 0.890
  Time: 0.895
  Time: 0.915
  Time: 1.001
  Time: 0.899

   Performance counter stats for './hackbench 10' (5 runs):

          16630  kmem:mm_page_alloc         ( +-   3.542% )
          11486  kmem:mm_page_free	    ( +-   4.771% )
           4730  kmem:mm_page_free_batched  ( +-   2.325% )

    0.982653002  seconds time elapsed   ( +-   1.448% )

In the event that some higher-level event is required that depends on some
aggregation of discrete events, then a script would need to be developed.

Using --repeat, it is also possible to view how events are fluctuating over
time on a system-wide basis using -a and sleep.
::

  $ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free \
		-e kmem:mm_page_free_batched \
		-a --repeat 10 \
		sleep 1
  Performance counter stats for 'sleep 1' (10 runs):

           1066  kmem:mm_page_alloc         ( +-  26.148% )
            182  kmem:mm_page_free          ( +-   5.464% )
            890  kmem:mm_page_free_batched  ( +-  30.079% )

    1.002251757  seconds time elapsed   ( +-   0.005% )

trace_pipe 후처리와 higher-level event

event가 활성화되면 발생한 event를 `/sys/kernel/tracing/trace_pipe`에서 사람이 읽을 수 있는 형식으로 읽을 수 있으며 binary option도 있습니다. output을 online으로 후처리하면 추가 정보를 계산할 수 있습니다.

후처리 예로 event를 발생시킨 PID의 `/proc` 정보를 읽기, 여러 lower-level event에서 higher-level event 도출, 두 event 사이 latency 계산이 있습니다.

`Documentation/trace/postprocess/trace-pagealloc-postprocess.pl`은 STDIN의 trace_pipe 또는 저장된 trace 사본을 읽는 예제입니다. online 실행 중 interrupt를 한 번 보내면 종료하지 않고 report를 만들고, 두 번 보내면 종료합니다.

script는 기본적으로 STDIN event를 세지만 더 복잡한 해석도 합니다. per-CPU list에서 main allocator로 여러 page가 반환되면 전용 tracepoint가 없어도 하나의 per-CPU drain으로 인식하고, PID나 개별 process 번호로 집계합니다.

외부 fragmentation 발생 시 severe 또는 moderate인지 보고하며, 매우 짧게 사는 process가 많은 event를 만들 때 parent를 기록해 helper를 대량 생성한 책임 process를 찾을 수 있습니다.

6. Higher-Level Analysis with Helper Scripts
============================================

When events are enabled the events that are triggering can be read from
/sys/kernel/tracing/trace_pipe in human-readable format although binary
options exist as well. By post-processing the output, further information can
be gathered on-line as appropriate. Examples of post-processing might include

  - Reading information from /proc for the PID that triggered the event
  - Deriving a higher-level event from a series of lower-level events.
  - Calculating latencies between two events

Documentation/trace/postprocess/trace-pagealloc-postprocess.pl is an example
script that can read trace_pipe from STDIN or a copy of a trace. When used
on-line, it can be interrupted once to generate a report without exiting
and twice to exit.

Simplistically, the script just reads STDIN and counts up events but it
also can do more such as

  - Derive high-level events from many low-level events. If a number of pages
    are freed to the main allocator from the per-CPU lists, it recognises
    that as one per-CPU drain even though there is no specific tracepoint
    for that event
  - It can aggregate based on PID or individual process number
  - In the event memory is getting externally fragmented, it reports
    on whether the fragmentation event was severe or moderate.
  - When receiving an event about a PID, it can record who the parent was so
    that if large numbers of events are coming from very short-lived
    processes, the parent process responsible for creating all the helpers
    can be identified

perf record와 report의 하위 수준 분석

kernel event를 발생시키는 program 내부 function을 식별하려면 먼저 data를 record해야 합니다. 문서 작성 당시 이 작업은 root 권한이 필요했습니다.

예제는 `-c 1`로 sample event period를 1로 설정하고 hackbench 실행 동안 세 page event를 기록합니다. 기본 sample period는 overhead를 줄이기 위해 높지만 그만큼 수집 정보가 거칠어질 수 있습니다.

  $ perf record -c 1 \
	-e kmem:mm_page_alloc -e kmem:mm_page_free \
	-e kmem:mm_page_free_batched \
	./hackbench 10
  Time: 0.894
  [ perf record: Captured and wrote 0.733 MB perf.data (~32010 samples) ]

record 결과는 `perf.data` file에 저장되고 `perf report`로 분석합니다.

  $ perf report
  # Samples: 30922
  #
  # Overhead    Command                     Shared Object
  # ........  .........  ................................
  #
      87.27%  hackbench  [vdso]
       6.85%  hackbench  /lib/i686/cmov/libc-2.9.so
       2.62%  hackbench  /lib/ld-2.9.so
       1.52%       perf  [vdso]
       1.22%  hackbench  ./hackbench
       0.48%  hackbench  [kernel]
       0.02%       perf  /lib/i686/cmov/libc-2.9.so
       0.01%       perf  /usr/bin/perf
       0.01%       perf  /lib/ld-2.9.so
       0.00%  hackbench  /lib/i686/cmov/libpthread-2.9.so
  #
  # (For more details, try: perf report --sort comm,dso,symbol)

report에서 event의 87.27%는 hackbench의 `[vdso]`, 6.85%는 libc, 2.62%는 dynamic linker에서 관찰됩니다. 간단한 binary에서는 VDSO 비중이 크게 나오는 경우가 흔합니다.

7. Lower-Level Analysis with PCL
================================

There may also be a requirement to identify what functions within a program
were generating events within the kernel. To begin this sort of analysis, the
data must be recorded. At the time of writing, this required root:
::

  $ perf record -c 1 \
	-e kmem:mm_page_alloc -e kmem:mm_page_free \
	-e kmem:mm_page_free_batched \
	./hackbench 10
  Time: 0.894
  [ perf record: Captured and wrote 0.733 MB perf.data (~32010 samples) ]

Note the use of '-c 1' to set the event period to sample. The default sample
period is quite high to minimise overhead but the information collected can be
very coarse as a result.

This record outputted a file called perf.data which can be analysed using
perf report.
::

  $ perf report
  # Samples: 30922
  #
  # Overhead    Command                     Shared Object
  # ........  .........  ................................
  #
      87.27%  hackbench  [vdso]
       6.85%  hackbench  /lib/i686/cmov/libc-2.9.so
       2.62%  hackbench  /lib/ld-2.9.so
       1.52%       perf  [vdso]
       1.22%  hackbench  ./hackbench
       0.48%  hackbench  [kernel]
       0.02%       perf  /lib/i686/cmov/libc-2.9.so
       0.01%       perf  /usr/bin/perf
       0.01%       perf  /lib/ld-2.9.so
       0.00%  hackbench  /lib/i686/cmov/libpthread-2.9.so
  #
  # (For more details, try: perf report --sort comm,dso,symbol)
  #

Xorg allocation event의 library와 symbol 찾기

단순 binary의 VDSO 편향을 피하기 위해 문서는 page allocation을 매우 많이 만들던 X process를 다른 예로 분석합니다.

`perf record -c 1 -f`에 X의 PID를 지정해 몇 초 동안 event를 기록합니다.

  $ perf record -c 1 -f \
		-e kmem:mm_page_alloc -e kmem:mm_page_free \
		-e kmem:mm_page_free_batched \
		-p `pidof X`

첫 report에서는 sample의 51.95%가 `[vdso]`, 47.95%가 `libpixman-1.so.0.13.1`에 있으므로 거의 절반이 library에서 발생했음을 알 수 있습니다.

  $ perf report
  # Samples: 27666
  #
  # Overhead  Command                            Shared Object
  # ........  .......  .......................................
  #
      51.95%     Xorg  [vdso]
      47.95%     Xorg  /opt/gfx-test/lib/libpixman-1.so.0.13.1
       0.09%     Xorg  /lib/i686/cmov/libc-2.9.so
       0.01%     Xorg  [kernel]
  #
  # (For more details, try: perf report --sort comm,dso,symbol)

어느 symbol인지 확인하려고 `perf report --sort comm,dso,symbol`을 실행하면 pixman library의 `pixmanFillsse2`가 47.93%를 차지합니다. libc의 `_int_malloc`, kernel의 `read_hpet`, `ftrace_trace_userstack` 같은 symbol도 그대로 표시됩니다.

  $ perf report --sort comm,dso,symbol
  # Samples: 27666
  #
  # Overhead  Command                            Shared Object  Symbol
  # ........  .......  .......................................  ......
  #
      51.95%     Xorg  [vdso]                                   [.] 0x000000ffffe424
      47.93%     Xorg  /opt/gfx-test/lib/libpixman-1.so.0.13.1  [.] pixmanFillsse2
       0.09%     Xorg  /lib/i686/cmov/libc-2.9.so               [.] _int_malloc
       0.01%     Xorg  /opt/gfx-test/lib/libpixman-1.so.0.13.1  [.] pixman_region32_copy_f
       0.01%     Xorg  [kernel]                                 [k] read_hpet
       0.01%     Xorg  /opt/gfx-test/lib/libpixman-1.so.0.13.1  [.] get_fast_path
       0.00%     Xorg  [kernel]                                 [k] ftrace_trace_userstack

According to this, the vast majority of events triggered on events
within the VDSO. With simple binaries, this will often be the case so let's
take a slightly different example. In the course of writing this, it was
noticed that X was generating an insane amount of page allocations so let's look
at it:
::

  $ perf record -c 1 -f \
		-e kmem:mm_page_alloc -e kmem:mm_page_free \
		-e kmem:mm_page_free_batched \
		-p `pidof X`

This was interrupted after a few seconds and
::

  $ perf report
  # Samples: 27666
  #
  # Overhead  Command                            Shared Object
  # ........  .......  .......................................
  #
      51.95%     Xorg  [vdso]
      47.95%     Xorg  /opt/gfx-test/lib/libpixman-1.so.0.13.1
       0.09%     Xorg  /lib/i686/cmov/libc-2.9.so
       0.01%     Xorg  [kernel]
  #
  # (For more details, try: perf report --sort comm,dso,symbol)
  #

So, almost half of the events are occurring in a library. To get an idea which
symbol:
::

  $ perf report --sort comm,dso,symbol
  # Samples: 27666
  #
  # Overhead  Command                            Shared Object  Symbol
  # ........  .......  .......................................  ......
  #
      51.95%     Xorg  [vdso]                                   [.] 0x000000ffffe424
      47.93%     Xorg  /opt/gfx-test/lib/libpixman-1.so.0.13.1  [.] pixmanFillsse2
       0.09%     Xorg  /lib/i686/cmov/libc-2.9.so               [.] _int_malloc
       0.01%     Xorg  /opt/gfx-test/lib/libpixman-1.so.0.13.1  [.] pixman_region32_copy_f
       0.01%     Xorg  [kernel]                                 [k] read_hpet
       0.01%     Xorg  /opt/gfx-test/lib/libpixman-1.so.0.13.1  [.] get_fast_path
       0.00%     Xorg  [kernel]                                 [k] ftrace_trace_userstack

perf annotate로 instruction hotspot 확인

`pixmanFillsse2` 안의 어느 instruction에서 문제가 나타나는지 `perf annotate pixmanFillsse2`로 확인합니다.

  $ perf annotate pixmanFillsse2
  [ ... ]
    0.00 :         34eeb:       0f 18 08                prefetcht0 (%eax)
         :      }
         :
         :      extern __inline void __attribute__((__gnu_inline__, __always_inline__, _
         :      _mm_store_si128 (__m128i *__P, __m128i __B) :      {
         :        *__P = __B;
   12.40 :         34eee:       66 0f 7f 80 40 ff ff    movdqa %xmm0,-0xc0(%eax)
    0.00 :         34ef5:       ff
   12.40 :         34ef6:       66 0f 7f 80 50 ff ff    movdqa %xmm0,-0xb0(%eax)
    0.00 :         34efd:       ff
   12.39 :         34efe:       66 0f 7f 80 60 ff ff    movdqa %xmm0,-0xa0(%eax)
    0.00 :         34f05:       ff
   12.67 :         34f06:       66 0f 7f 80 70 ff ff    movdqa %xmm0,-0x90(%eax)
    0.00 :         34f0d:       ff
   12.58 :         34f0e:       66 0f 7f 40 80          movdqa %xmm0,-0x80(%eax)
   12.31 :         34f13:       66 0f 7f 40 90          movdqa %xmm0,-0x70(%eax)
   12.40 :         34f18:       66 0f 7f 40 a0          movdqa %xmm0,-0x60(%eax)
   12.31 :         34f1d:       66 0f 7f 40 b0          movdqa %xmm0,-0x50(%eax)

annotate 결과에서 연속된 `movdqa` store instruction마다 약 12.31~12.67%가 귀속됩니다. 얼핏 보면 pixmap을 card로 복사하는 데 시간이 소비됩니다.

pixmap이 왜 이렇게 많이 복사되는지는 추가 조사가 필요하지만, 출발점은 수개월 전 잊힌 채 library path에 남아 있던 오래된 libpixmap build를 제거하는 것입니다.

To see where within the function pixmanFillsse2 things are going wrong:
::

  $ perf annotate pixmanFillsse2
  [ ... ]
    0.00 :         34eeb:       0f 18 08                prefetcht0 (%eax)
         :      }
         :
         :      extern __inline void __attribute__((__gnu_inline__, __always_inline__, _
         :      _mm_store_si128 (__m128i *__P, __m128i __B) :      {
         :        *__P = __B;
   12.40 :         34eee:       66 0f 7f 80 40 ff ff    movdqa %xmm0,-0xc0(%eax)
    0.00 :         34ef5:       ff
   12.40 :         34ef6:       66 0f 7f 80 50 ff ff    movdqa %xmm0,-0xb0(%eax)
    0.00 :         34efd:       ff
   12.39 :         34efe:       66 0f 7f 80 60 ff ff    movdqa %xmm0,-0xa0(%eax)
    0.00 :         34f05:       ff
   12.67 :         34f06:       66 0f 7f 80 70 ff ff    movdqa %xmm0,-0x90(%eax)
    0.00 :         34f0d:       ff
   12.58 :         34f0e:       66 0f 7f 40 80          movdqa %xmm0,-0x80(%eax)
   12.31 :         34f13:       66 0f 7f 40 90          movdqa %xmm0,-0x70(%eax)
   12.40 :         34f18:       66 0f 7f 40 a0          movdqa %xmm0,-0x60(%eax)
   12.31 :         34f1d:       66 0f 7f 40 b0          movdqa %xmm0,-0x50(%eax)

At a glance, it looks like the time is being spent copying pixmaps to
the card.  Further investigation would be needed to determine why pixmaps
are being copied around so much but a starting point would be to take an
ancient build of libpixmap out of the library path where it was totally
forgotten about from months ago!