On Tue, 12 Feb 2013, Richard Lowe wrote:
Presumably there's a 'hotkernel.d', or a simple oneline:
profile-997hz / execname == "magick" / { @[stack()] = count(); }
To give you an idea where you're spending your system time. You also
appear to have slept 2 seconds in the example you gave, so you may
want to look into whether that was just being preempted, or I/O or ...
I am rather concerned about the missing 2 seconds and also that there
is an extra 1.80 seconds of system time compared with Linux. I
notice that if I use 'ptime' to do the timing, then repeated runs are
within tens of milliseconds in reported completion time but if I use
'time' from the zsh shell, there is quite considerable jitter in the
reported system and total time:
./magick large.gif 5.88s user 3.08s system 89% cpu 10.060 total
./magick large.gif 5.86s user 3.64s system 85% cpu 11.134 total
./magick large.gif 5.90s user 3.11s system 88% cpu 10.200 total
./magick large.gif 5.86s user 3.65s system 85% cpu 11.143 total
./magick large.gif 5.86s user 3.07s system 89% cpu 10.027 total
./magick large.gif 5.86s user 3.64s system 85% cpu 11.153 total
./magick large.gif 5.90s user 3.07s system 89% cpu 10.063 total
./magick large.gif 5.85s user 3.65s system 85% cpu 11.149 total
./magick large.gif 5.88s user 3.15s system 89% cpu 10.143 total
I see the same jitter using 'time' from /bin/sh so it is not shell
specific. The same jitter is noticed with time output to a file so it
is not specific to the login terminal.
Ptime outputs are rock solid with no jitter:
real 9.518479762
user 5.866223863
sys 3.651032686
real 9.518130784
user 5.864821310
sys 3.651798091
real 9.502513011
user 5.858180321
sys 3.643405153
The system is very idle (but warmed up) and I remote login with no
login at the console. The zfs pool is very fast with 8 SAS disks
arranged as mirrors. The program is reading data from zfs ARC and
does not write any data at all.
The user time reported by 'ptime' is similar to the user time reported
by collect/analyzer but the system time reported by 'ptime' is a half
second more than reported by the profiler and 'time' reports yet more
mysterious lost time.
The 'hotkernel' dtrace script reports:
genunix`anon_decref 134 0.0%
unix`0xfffffffffb80 199 0.1%
unix`page_lookup_create 353 0.1%
unix`mutex_enter 694 0.3%
unix`hwblkclr 1012 0.4%
unix`i86_mwait 26355 9.5%
unix`acpi_cpu_cstate 245493 88.8%
The primary issue I am looking to solve (this program is just an
interesting case study) is that OpenIndiana is very slow to execute
the normal GraphicsMagick command line program 'gm'. There seems to
be quite a lot of overhead associated with starting and stopping the
program which does not show up in any profiler. Recently a 'batch'
mode was added which allows many commands to be executed in the same
process and this batch mode runs 2X times faster than executing the
same individual commands in a shell script under OpenIndiana. Under
Linux and FreeBSD there is perhaps a 6% advantage (or less).
Benchmark testing shows that with large data and many cycles in the
same process, performance is as expected between the more powerful
OpenIndiana system and the less powerful Linux system (execution is
faster on the more powerful system as should be expected).
Single-shot execution where the process is started, allocates memory,
does some CPU/memory crunching, releases all allocated memory, and
then quits, is where the performance problem is.
Any more ideas about what to look at?
Bob
--
Bob Friesenhahn
[email protected], http://www.simplesystems.org/users/bfriesen/
GraphicsMagick Maintainer, http://www.GraphicsMagick.org/
-------------------------------------------
illumos-discuss
Archives: https://www.listbox.com/member/archive/182180/=now
RSS Feed: https://www.listbox.com/member/archive/rss/182180/21175430-2e6923be
Modify Your Subscription:
https://www.listbox.com/member/?member_id=21175430&id_secret=21175430-6a77cda4
Powered by Listbox: http://www.listbox.com
