runsolver Copyright (C) 2010 Olivier ROUSSEL

This is runsolver version 3.2.9a (svn: 651)

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

command line: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012070034/apt-pbo-trendy-1.0.6/rand815.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./apt-pbo-trendy-1.0.6 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand815.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012070034/apt-pbo-trendy-1.0.6/rand815.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 seconds
Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB
Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.35 1.21 1.07 1/44 25527
/proc/meminfo: memFree=957440/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=3024 CPUtime=0
/proc/25527/stat : 25527 (runsolver) D 25526 25527 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 20 0 1 0 882730100 3096576 94 1283457024 134512640 134586868 4292544144 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/25527/statm: 756 94 62 19 0 54 0

[startup+0.11277 s]
/proc/loadavg: 1.35 1.21 1.07 1/44 25527
/proc/meminfo: memFree=957440/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1676

[startup+0.204776 s]
/proc/loadavg: 1.35 1.21 1.07 1/44 25527
/proc/meminfo: memFree=957440/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1676

[startup+0.304774 s]
/proc/loadavg: 1.35 1.21 1.07 1/44 25527
/proc/meminfo: memFree=957440/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1676

[startup+0.714315 s]
/proc/loadavg: 1.35 1.21 1.07 1/44 25527
/proc/meminfo: memFree=957440/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1676

[startup+1.51447 s]
/proc/loadavg: 1.32 1.20 1.07 2/47 25533
/proc/meminfo: memFree=934648/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
[pid=25530] ppid=25527 vsize=8356 CPUtime=0.01
/proc/25530/stat : 25530 (apt-pbo) S 25527 25527 4159 34819 4229 4202496 1583 411 30 0 0 1 0 0 21 0 1 0 882730100 8556544 1422 1283457024 134512640 135744540 4286826832 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/25530/statm: 2089 1422 646 301 0 822 0
[pid=25533] ppid=25530 vsize=22612 CPUtime=0.95
/proc/25533/stat : 25533 (cudftodeb.nativ) R 25530 25527 4159 34819 4229 4202496 5330 0 11 0 95 0 0 0 25 0 1 0 882730146 23154688 5258 1283457024 134512640 135029684 4287086656 18446744073709551615 135011919 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/25533/statm: 5653 5258 247 127 0 5036 0
Current children cumulated CPU time (s) 0.96
Current children cumulated vsize (KiB) 32644

[startup+3.11477 s]
/proc/loadavg: 1.32 1.20 1.07 2/47 25533
/proc/meminfo: memFree=906524/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
[pid=25530] ppid=25527 vsize=8356 CPUtime=0.01
/proc/25530/stat : 25530 (apt-pbo) S 25527 25527 4159 34819 4229 4202496 1583 411 30 0 0 1 0 0 21 0 1 0 882730100 8556544 1422 1283457024 134512640 135744540 4286826832 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/25530/statm: 2089 1422 646 301 0 822 0
[pid=25533] ppid=25530 vsize=54120 CPUtime=2.55
/proc/25533/stat : 25533 (cudftodeb.nativ) R 25530 25527 4159 34819 4229 4202496 13051 0 11 0 252 3 0 0 25 0 1 0 882730146 55418880 12979 1283457024 134512640 135029684 4287086656 18446744073709551615 4158932559 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/25533/statm: 13530 12979 247 127 0 12913 0
Current children cumulated CPU time (s) 2.56
Current children cumulated vsize (KiB) 64152

[startup+6.30859 s]
/proc/loadavg: 1.32 1.20 1.07 2/47 25533
/proc/meminfo: memFree=832668/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
[pid=25530] ppid=25527 vsize=8356 CPUtime=0.01
/proc/25530/stat : 25530 (apt-pbo) S 25527 25527 4159 34819 4229 4202496 1583 411 30 0 0 1 0 0 21 0 1 0 882730100 8556544 1422 1283457024 134512640 135744540 4286826832 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/25530/statm: 2089 1422 646 301 0 822 0
[pid=25533] ppid=25530 vsize=107296 CPUtime=5.73
/proc/25533/stat : 25533 (cudftodeb.nativ) R 25530 25527 4159 34819 4229 4202496 26218 0 11 0 532 41 0 0 25 0 1 0 882730146 109871104 26146 1283457024 134512640 135029684 4287086656 18446744073709551615 134885856 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/25533/statm: 26824 26146 258 127 0 26207 0
Current children cumulated CPU time (s) 5.74
Current children cumulated vsize (KiB) 117328

[startup+12.7153 s]
/proc/loadavg: 1.35 1.21 1.07 2/48 25541
/proc/meminfo: memFree=877344/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
[pid=25530] ppid=25527 vsize=8356 CPUtime=9.69
/proc/25530/stat : 25530 (apt-pbo) S 25527 25527 4159 34819 4229 4202496 1758 30094 30 11 0 1 826 142 19 0 1 0 882730100 8556544 1448 1283457024 134512640 135744540 4286826832 18446744073709551615 4294960130 0 0 135 0 18446744071564329979 0 0 17 0 0 0 0
/proc/25530/statm: 2089 1448 651 301 0 822 0
[pid=25534] ppid=25530 vsize=2572 CPUtime=0
/proc/25534/stat : 25534 (apt-get.sh) S 25530 25527 4159 34819 4229 4202496 400 490 11 0 0 0 0 0 20 0 1 0 882731146 2633728 275 1283457024 134512640 135304128 4287315616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25534/statm: 643 275 235 194 0 29 0
[pid=25537] ppid=25534 vsize=52748 CPUtime=1.51
/proc/25537/stat : 25537 (apt-get) R 25534 25527 4159 34819 4229 4202496 6880 1680 382 0 115 0 33 3 19 0 1 0 882731157 54013952 7130 1283457024 134512640 134649604 4294154560 18446744073709551615 4159726976 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/25537/statm: 13187 7130 7074 34 0 69 0
Current children cumulated CPU time (s) 11.2
Current children cumulated vsize (KiB) 65352

Solver just ended. Dumping a history of the last processes samples

[startup+12.8056 s]
/proc/loadavg: 1.35 1.21 1.07 2/48 25541
/proc/meminfo: memFree=877344/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
[pid=25530] ppid=25527 vsize=8356 CPUtime=9.69
/proc/25530/stat : 25530 (apt-pbo) S 25527 25527 4159 34819 4229 4202496 1758 30094 30 11 0 1 826 142 19 0 1 0 882730100 8556544 1448 1283457024 134512640 135744540 4286826832 18446744073709551615 4294960130 0 0 135 0 18446744071564329979 0 0 17 0 0 0 0
/proc/25530/statm: 2089 1448 651 301 0 822 0
[pid=25534] ppid=25530 vsize=2572 CPUtime=0
/proc/25534/stat : 25534 (apt-get.sh) S 25530 25527 4159 34819 4229 4202496 400 490 11 0 0 0 0 0 20 0 1 0 882731146 2633728 275 1283457024 134512640 135304128 4287315616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25534/statm: 643 275 235 194 0 29 0
[pid=25537] ppid=25534 vsize=52748 CPUtime=1.56
/proc/25537/stat : 25537 (apt-get) R 25534 25527 4159 34819 4229 4202496 6913 1680 383 0 115 5 33 3 19 0 1 0 882731157 54013952 7164 1283457024 134512640 134649604 4294154560 18446744073709551615 4294960130 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/25537/statm: 13187 7164 7108 34 0 69 0
Current children cumulated CPU time (s) 11.25
Current children cumulated vsize (KiB) 65352

[startup+19.2074 s]
/proc/loadavg: 1.33 1.21 1.07 2/48 25546
/proc/meminfo: memFree=826444/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
[pid=25530] ppid=25527 vsize=38436 CPUtime=12.02
/proc/25530/stat : 25530 (apt-pbo) S 25527 25527 4159 34819 4229 4202496 9423 40659 30 424 38 35 978 151 18 0 1 0 882730100 39358464 8614 1283457024 134512640 135744540 4286826832 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/25530/statm: 9609 8614 7158 301 0 1495 0
[pid=25543] ppid=25530 vsize=2580 CPUtime=0
/proc/25543/stat : 25543 (apt-get.sh) S 25530 25527 4159 34819 4229 4202496 468 490 0 0 0 0 0 0 18 0 1 0 882731555 2641920 278 1283457024 134512640 135304128 4291466528 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25543/statm: 645 278 235 194 0 31 0
[pid=25546] ppid=25543 vsize=34252 CPUtime=4.17
/proc/25546/stat : 25546 (apt-get) R 25543 25527 4159 34819 4229 4202496 7790 0 0 0 361 56 0 0 25 0 1 0 882731556 35074048 7638 1283457024 134512640 134649604 4289856448 18446744073709551615 4158895936 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/25546/statm: 8563 7638 6855 34 0 806 0
Current children cumulated CPU time (s) 16.19
Current children cumulated vsize (KiB) 76944

[startup+20.8106 s]
/proc/loadavg: 1.33 1.21 1.07 2/48 25546
/proc/meminfo: memFree=825328/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
[pid=25530] ppid=25527 vsize=38436 CPUtime=12.28
/proc/25530/stat : 25530 (apt-pbo) S 25527 25527 4159 34819 4229 4202496 9423 40659 30 424 51 48 978 151 18 0 1 0 882730100 39358464 8614 1283457024 134512640 135744540 4286826832 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/25530/statm: 9609 8614 7158 301 0 1495 0
[pid=25543] ppid=25530 vsize=2580 CPUtime=0
/proc/25543/stat : 25543 (apt-get.sh) S 25530 25527 4159 34819 4229 4202496 468 490 0 0 0 0 0 0 18 0 1 0 882731555 2641920 278 1283457024 134512640 135304128 4291466528 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25543/statm: 645 278 235 194 0 31 0
[pid=25546] ppid=25543 vsize=34252 CPUtime=5.4
/proc/25546/stat : 25546 (apt-get) R 25543 25527 4159 34819 4229 4202496 7801 0 0 0 461 79 0 0 25 0 1 0 882731556 35074048 7649 1283457024 134512640 134649604 4289856448 18446744073709551615 4157130149 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/25546/statm: 8563 7649 6855 34 0 806 0
Current children cumulated CPU time (s) 17.68
Current children cumulated vsize (KiB) 76944

[startup+22.4108 s]
/proc/loadavg: 1.30 1.20 1.07 2/48 25546
/proc/meminfo: memFree=822724/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
[pid=25530] ppid=25527 vsize=38436 CPUtime=12.6
/proc/25530/stat : 25530 (apt-pbo) S 25527 25527 4159 34819 4229 4202496 9423 40659 30 424 67 64 978 151 18 0 1 0 882730100 39358464 8614 1283457024 134512640 135744540 4286826832 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/25530/statm: 9609 8614 7158 301 0 1495 0
[pid=25543] ppid=25530 vsize=2580 CPUtime=0
/proc/25543/stat : 25543 (apt-get.sh) S 25530 25527 4159 34819 4229 4202496 468 490 0 0 0 0 0 0 18 0 1 0 882731555 2641920 278 1283457024 134512640 135304128 4291466528 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25543/statm: 645 278 235 194 0 31 0
[pid=25546] ppid=25543 vsize=34252 CPUtime=6.68
/proc/25546/stat : 25546 (apt-get) R 25543 25527 4159 34819 4229 4202496 7815 0 0 0 568 100 0 0 25 0 1 0 882731556 35074048 7663 1283457024 134512640 134649604 4289856448 18446744073709551615 4158847196 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/25546/statm: 8563 7663 6856 34 0 806 0
Current children cumulated CPU time (s) 19.28
Current children cumulated vsize (KiB) 76944

[startup+22.8107 s]
/proc/loadavg: 1.30 1.20 1.07 2/48 25546
/proc/meminfo: memFree=822724/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
[pid=25530] ppid=25527 vsize=40488 CPUtime=19.47
/proc/25530/stat : 25530 (apt-pbo) S 25527 25527 4159 34819 4229 4202496 10051 49445 30 424 67 66 1553 261 18 0 1 0 882730100 41459712 9130 1283457024 134512640 135744540 4286826832 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/25530/statm: 10122 9130 7161 301 0 2008 0
Current children cumulated CPU time (s) 19.47
Current children cumulated vsize (KiB) 42164

[startup+23.0063 s]
/proc/loadavg: 1.30 1.20 1.07 2/48 25546
/proc/meminfo: memFree=822724/1048576 swapFree=2077620/2097144
[pid=25527] ppid=25526 vsize=1676 CPUtime=0
/proc/25527/stat : 25527 (sh) S 25526 25527 4159 34819 4229 4202496 222 175 0 0 0 0 0 0 21 0 1 0 882730100 1716224 128 1283457024 134512640 134594024 4287314592 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25527/statm: 419 128 112 20 0 45 0
[pid=25530] ppid=25527 vsize=38492 CPUtime=19.51
/proc/25530/stat : 25530 (apt-pbo) R 25527 25527 4159 34819 4229 4202496 10381 49445 30 424 69 68 1553 261 18 0 1 0 882730100 39415808 8648 1283457024 134512640 135744540 4286826832 18446744073709551615 4294960130 0 0 128 0 0 0 0 17 0 0 0 0
/proc/25530/statm: 9623 8648 7162 301 0 1509 0
Current children cumulated CPU time (s) 19.51
Current children cumulated vsize (KiB) 40168

Child status: 0
Real time (s): 23.0145
CPU time (s): 19.5332
CPU user time (s): 16.225
CPU system time (s): 3.30821
CPU usage (%): 84.8735
Max. virtual memory (cumulated for all children) (KiB): 128416

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 16.225
system time used= 3.30821
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 60364
page faults= 454
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 178410
involuntary context switches= 178344

runsolver used 0 second user time and 0 second system time

The end