Re: performance of jailed processes

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