performance of jailed processes
Dag-ErlingSmørgrav
des at des.no
Tue Mar 30 13:43:07 PST 2004
Robert Watson <rwatson at freebsd.org> writes:
> Somewhat more painful suggestion, but could you generate ktraces against a
> mysql client doing the query inside and out of jail, then using whatever
> flag sets relative timestamps on kdump, diff the two and see where the
> substantial differences begin?
OK, ktrace shows some interesting differences. I used ktrace -tcsw to
get syscalls, signals and context switches.
Here's mysql outside the jail reading the row returned from the query
(from kdump -tcs -R):
12698 mysql 0.000219 CALL read(0x3,0x806b000,0x82af)
12698 mysql 0.000117 RET read 27981/0x6d4d
12698 mysql 0.000029 CALL read(0x3,0x8071d4d,0x1562)
12698 mysql 0.000189 RET read 2896/0xb50
12698 mysql 0.000005 CALL read(0x3,0x807289d,0xa12)
12698 mysql 0.000394 RET read 2578/0xa12
here's mysql inside the jail doing the same thing:
12703 mysql 0.000264 CALL read(0x3,0x8070000,0x82af)
12703 mysql 0.000043 RET read 469/0x1d5
12703 mysql 0.000005 CALL read(0x3,0x80701d5,0x80da)
12703 mysql 1.208382 RET read 4344/0x10f8
12703 mysql 0.001126 CALL read(0x3,0x80712cd,0x6fe2)
12703 mysql 0.000027 RET read 1448/0x5a8
12703 mysql 0.000032 CALL read(0x3,0x8071875,0x6a3a)
12703 mysql 0.000183 RET read 1448/0x5a8
12703 mysql 0.000029 CALL read(0x3,0x8071e1d,0x6492)
12703 mysql 1.197240 RET read 1448/0x5a8
12703 mysql 0.000529 CALL read(0x3,0x80723c5,0x5eea)
12703 mysql 1.199249 RET read 2896/0xb50
12703 mysql 0.000535 CALL read(0x3,0x8072f15,0x539a)
12703 mysql 1.199303 RET read 2896/0xb50
12703 mysql 0.000701 CALL read(0x3,0x8073a65,0x484a)
12703 mysql 0.002045 RET read 2896/0xb50
12703 mysql 0.000028 CALL read(0x3,0x80745b5,0x3cfa)
12703 mysql 1.197229 RET read 1448/0x5a8
12703 mysql 0.000261 CALL read(0x3,0x8074b5d,0x3752)
12703 mysql 1.200116 RET read 2896/0xb50
12703 mysql 0.001101 CALL read(0x3,0x80756ad,0x2c02)
12703 mysql 1.199051 RET read 2896/0xb50
12703 mysql 0.000307 CALL read(0x3,0x80761fd,0x20b2)
12703 mysql 1.200152 RET read 2896/0xb50
12703 mysql 0.000735 CALL read(0x3,0x8076d4d,0x1562)
12703 mysql 1.198556 RET read 2896/0xb50
12703 mysql 0.000135 CALL read(0x3,0x807789d,0xa12)
12703 mysql 0.001835 RET read 2578/0xa12
12703 mysql 0.000208 CALL break(0x8083000)
12703 mysql 0.000009 RET break 0
let's look at an inside trace *with* context switches and see where
the longest delays (>= 0.1 s) are:
# kdump -R | egrep -B1 ' (0\.[1-9]|1\.[0-9])'
12703 mysql 0.000003 CSW stop kernel
12703 mysql 1.193959 CSW resume kernel
--
12703 mysql 0.000086 CSW stop kernel
12703 mysql 1.208101 CSW resume kernel
--
12703 mysql 0.000197 CSW stop kernel
12703 mysql 1.196910 CSW resume kernel
--
12703 mysql 0.000005 CSW stop kernel
12703 mysql 1.199010 CSW resume kernel
--
12703 mysql 0.000216 CSW stop kernel
12703 mysql 1.199035 CSW resume kernel
--
12703 mysql 0.000006 CSW stop kernel
12703 mysql 1.197189 CSW resume kernel
--
12703 mysql 0.000007 CSW stop kernel
12703 mysql 1.199705 CSW resume kernel
--
12703 mysql 0.000747 CSW stop kernel
12703 mysql 1.198046 CSW resume kernel
--
12703 mysql 0.000206 CSW stop kernel
12703 mysql 1.199760 CSW resume kernel
--
12703 mysql 0.000250 CSW stop kernel
12703 mysql 1.198188 CSW resume kernel
oops, they're all in context switches...
DES
--
Dag-Erling Smørgrav - des at des.no
More information about the freebsd-current
mailing list