Client executes very slowly, takes 100% CPU

[naapuri]

When running the bcfg2 client with

bcfg2 -e -v -d -k -q -r all -n

the client executes very slowly and takes 100% CPU. Here is a strace on the client process:

# strace -r -eall -p19595
Process 19595 attached - interrupt to quit
     0.000000 brk(0x929f000)            = 0x929f000
     0.001129 futex(0x81469c0, FUTEX_WAKE, 1) = 0
     0.000733 brk(0x929b000)            = 0x929b000
     0.000631 brk(0x928f000)            = 0x928f000
     0.000725 brk(0x928c000)            = 0x928c000
     0.001404 poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 90000) = 1
     0.000542 recv(3, "\27", 1, 0)      = 1
     0.000433 poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 90000) = 1
     0.000292 recv(3, "\3\[email protected]", 4, 0)   = 4
     0.000411 poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 90000) = 1
     0.000286 recv(3, "\367\322\373\346\365\335\336\334i\227\311\23 \310\242\240"..., 16432, 0) = 16432
     0.569021 brk(0x92b0000)            = 0x92b0000
     0.001094 futex(0x81469c0, FUTEX_WAKE, 1) = 0
     0.000733 brk(0x92ac000)            = 0x92ac000
     0.000631 brk(0x92a0000)            = 0x92a0000
     0.000710 brk(0x929d000)            = 0x929d000
     0.001381 poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 90000) = 1
     0.000467 recv(3, "\27", 1, 0)      = 1
     0.000436 poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 90000) = 1
     0.000278 recv(3, "\3\[email protected]", 4, 0)   = 4
     0.000406 poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 90000) = 1
     0.000280 recv(3, "\321\242\10\2310\3119\340\344\334\313\344V\252\2053\355"..., 16432, 0) = 16432
     0.562301 brk(0x92c1000)            = 0x92c1000
     0.001104 futex(0x81469c0, FUTEX_WAKE, 1) = 0
     0.000702 brk(0x92bd000)            = 0x92bd000
     0.000623 brk(0x92b1000)            = 0x92b1000
     0.000722 brk(0x92ae000)            = 0x92ae000
     0.001397 poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 90000) = 1
     0.000505 recv(3, "\27", 1, 0)      = 1
     0.000413 poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 90000) = 1
     0.000274 recv(3, "\3\[email protected]", 4, 0)   = 4
     0.000410 poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 90000) = 1
     0.000281 recv(3, "b\224\36Z\342\336\225*C`eP\"~T\306\255\326&\250\304\277"..., 16432, 0) = 16432
...

The server log seems normal:

Generated config for foo in 0.147306919098 seconds
[5 minutes later:]
Client foo reported state clean

I'm running svn2999 on a Debian etch.

[naapuri]

Here is the OpStamps? information for this run:

1175504557.56 start
1175504557.86 probe_download
1175504557.86 probe_upload
1175504845.7 config_download
1175504845.79 config_parse
1175504845.79 initialization
1175504847.06 inventory
1175504847.07 finished
1175504847.07 install
1175504847.07 remove

[desai]

The OpStamps are unix timestamps from when operations have completed. In this case, it looks like the step that is taking a lot of time is the config_download step (~300 seconds)

Does it help if you add python-m2crypto on the client and server? (with a server restart) I wonder if you are being bitten by the new python tls code (that is slower than pyopenssl)

[desai]

OK, so this is definitely a TLS performance issue. We will need to document this better.