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/201012091434/cudf2pbo4user-1.0/1dcce248-4bb4-11df-9e6e-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./cudf2pbo4user-1.0 /home/misc2010/data/2010/debian-dudf//1dcce248-4bb4-11df-9e6e-00163e7a6f5e.cudf /home/misc2010/tmp/201012091434/cudf2pbo4user-1.0/1dcce248-4bb4-11df-9e6e-00163e7a6f5e.cudf.debian-dudf.result -changed,-removed,-unmet_recommends,-new 

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.12 0.91 0.48 3/38 26123
/proc/meminfo: memFree=424932/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=0
/proc/26122/stat : 26122 (cudf2pbo4user-1) S 26121 26122 25521 34816 25544 4202496 383 0 0 0 0 0 0 0 18 0 1 0 899870500 2629632 280 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26122/statm: 642 280 240 194 0 28 0
[pid=26123] ppid=26122 vsize=2568 CPUtime=0
/proc/26123/stat : 26123 (cudf2pbo4user-1) D 26122 26122 25521 34816 25544 4202560 79 0 0 0 0 0 0 0 18 0 1 0 899870500 2629632 103 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 0 0 0 18446744071564252162 0 0 17 0 0 0 0
/proc/26123/statm: 642 103 62 194 0 28 0

[startup+0.129242 s]
/proc/loadavg: 1.12 0.91 0.48 3/38 26123
/proc/meminfo: memFree=424932/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=0
/proc/26122/stat : 26122 (cudf2pbo4user-1) S 26121 26122 25521 34816 25544 4202496 383 0 0 0 0 0 0 0 18 0 1 0 899870500 2629632 280 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26122/statm: 642 280 240 194 0 28 0
[pid=26123] ppid=26122 vsize=6008 CPUtime=0.09
/proc/26123/stat : 26123 (cudf_msu32) R 26122 26122 25521 34816 25544 4202496 1325 0 0 0 8 1 0 0 25 0 1 0 899870500 6152192 1218 1283457024 134512640 136125367 4287140560 18446744073709551615 134738369 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/26123/statm: 1502 1218 145 394 0 1106 0
Current children cumulated CPU time (s) 0.09
Current children cumulated vsize (KiB) 8576

[startup+0.210889 s]
/proc/loadavg: 1.12 0.91 0.48 3/38 26123
/proc/meminfo: memFree=424932/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=0
/proc/26122/stat : 26122 (cudf2pbo4user-1) S 26121 26122 25521 34816 25544 4202496 383 0 0 0 0 0 0 0 18 0 1 0 899870500 2629632 280 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26122/statm: 642 280 240 194 0 28 0
[pid=26123] ppid=26122 vsize=9176 CPUtime=0.17
/proc/26123/stat : 26123 (cudf_msu32) R 26122 26122 25521 34816 25544 4202496 2112 0 0 0 16 1 0 0 25 0 1 0 899870500 9396224 2005 1283457024 134512640 136125367 4287140560 18446744073709551615 134717779 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/26123/statm: 2294 2005 145 394 0 1898 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 11744

[startup+0.310907 s]
/proc/loadavg: 1.12 0.91 0.48 3/38 26123
/proc/meminfo: memFree=424932/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=0
/proc/26122/stat : 26122 (cudf2pbo4user-1) S 26121 26122 25521 34816 25544 4202496 383 0 0 0 0 0 0 0 18 0 1 0 899870500 2629632 280 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26122/statm: 642 280 240 194 0 28 0
[pid=26123] ppid=26122 vsize=12440 CPUtime=0.28
/proc/26123/stat : 26123 (cudf_msu32) R 26122 26122 25521 34816 25544 4202496 2922 0 0 0 26 2 0 0 25 0 1 0 899870500 12738560 2815 1283457024 134512640 136125367 4287140560 18446744073709551615 135535052 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/26123/statm: 3110 2815 146 394 0 2714 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 15008

[startup+0.711004 s]
/proc/loadavg: 1.12 0.91 0.48 3/38 26123
/proc/meminfo: memFree=424932/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=0
/proc/26122/stat : 26122 (cudf2pbo4user-1) S 26121 26122 25521 34816 25544 4202496 383 0 0 0 0 0 0 0 18 0 1 0 899870500 2629632 280 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26122/statm: 642 280 240 194 0 28 0
[pid=26123] ppid=26122 vsize=23856 CPUtime=0.68
/proc/26123/stat : 26123 (cudf_msu32) R 26122 26122 25521 34816 25544 4202496 5776 0 0 0 64 4 0 0 25 0 1 0 899870500 24428544 5669 1283457024 134512640 136125367 4287140560 18446744073709551615 134717792 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/26123/statm: 5964 5669 146 394 0 5568 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 26424

[startup+1.51125 s]
/proc/loadavg: 1.12 0.91 0.48 2/39 26124
/proc/meminfo: memFree=392920/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=0
/proc/26122/stat : 26122 (cudf2pbo4user-1) S 26121 26122 25521 34816 25544 4202496 383 0 0 0 0 0 0 0 18 0 1 0 899870500 2629632 280 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26122/statm: 642 280 240 194 0 28 0
[pid=26123] ppid=26122 vsize=47628 CPUtime=1.47
/proc/26123/stat : 26123 (cudf_msu32) R 26122 26122 25521 34816 25544 4202496 11834 0 0 0 137 10 0 0 25 0 1 0 899870500 48771072 11628 1283457024 134512640 136125367 4287140560 18446744073709551615 134673087 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/26123/statm: 11907 11628 164 394 0 11511 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 50196

[startup+3.1129 s]
/proc/loadavg: 1.12 0.91 0.48 2/39 26124
/proc/meminfo: memFree=364028/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=2.58
/proc/26122/stat : 26122 (cudf2pbo4user-1) S 26121 26122 25521 34816 25544 4202496 401 14884 0 0 0 0 204 54 20 0 1 0 899870500 2629632 281 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26122/statm: 642 281 241 194 0 28 0
Current children cumulated CPU time (s) 2.58
Current children cumulated vsize (KiB) 2568

[startup+6.31396 s]
/proc/loadavg: 1.11 0.91 0.48 2/39 26125
/proc/meminfo: memFree=383496/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=2.58
/proc/26122/stat : 26122 (cudf2pbo4user-1) S 26121 26122 25521 34816 25544 4202496 401 14884 0 0 0 0 204 54 20 0 1 0 899870500 2629632 281 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26122/statm: 642 281 241 194 0 28 0
[pid=26125] ppid=26122 vsize=37408 CPUtime=3.65
/proc/26125/stat : 26125 (bmo-pblex32) R 26122 26122 25521 34816 25544 4202496 9949 0 0 0 320 45 0 0 25 0 1 0 899870765 38305792 8950 1283457024 134512640 135887319 4294343136 18446744073709551615 134615126 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26125/statm: 9352 8950 138 336 0 9014 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 39976

[startup+12.709 s]
/proc/loadavg: 1.10 0.91 0.48 2/39 26125
/proc/meminfo: memFree=367996/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=2.58
/proc/26122/stat : 26122 (cudf2pbo4user-1) S 26121 26122 25521 34816 25544 4202496 401 14884 0 0 0 0 204 54 20 0 1 0 899870500 2629632 281 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26122/statm: 642 281 241 194 0 28 0
[pid=26125] ppid=26122 vsize=63240 CPUtime=9.95
/proc/26125/stat : 26125 (bmo-pblex32) R 26122 26122 25521 34816 25544 4202496 20827 0 0 0 895 100 0 0 25 0 1 0 899870765 64757760 15500 1283457024 134512640 135887319 4294343136 18446744073709551615 134537240 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26125/statm: 15810 15500 144 336 0 15472 0
Current children cumulated CPU time (s) 12.53
Current children cumulated vsize (KiB) 65808

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

[startup+12.809 s]
/proc/loadavg: 1.10 0.91 0.48 2/39 26125
/proc/meminfo: memFree=367996/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=2.58
/proc/26122/stat : 26122 (cudf2pbo4user-1) S 26121 26122 25521 34816 25544 4202496 401 14884 0 0 0 0 204 54 20 0 1 0 899870500 2629632 281 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26122/statm: 642 281 241 194 0 28 0
[pid=26125] ppid=26122 vsize=65388 CPUtime=10.05
/proc/26125/stat : 26125 (bmo-pblex32) R 26122 26122 25521 34816 25544 4202496 21372 0 0 0 904 101 0 0 25 0 1 0 899870765 66957312 16039 1283457024 134512640 135887319 4294343136 18446744073709551615 134604731 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26125/statm: 16347 16039 144 336 0 16009 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 67956

[startup+14.4094 s]
/proc/loadavg: 1.09 0.91 0.49 2/39 26125
/proc/meminfo: memFree=340344/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=2.58
/proc/26122/stat : 26122 (cudf2pbo4user-1) S 26121 26122 25521 34816 25544 4202496 401 14884 0 0 0 0 204 54 20 0 1 0 899870500 2629632 281 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26122/statm: 642 281 241 194 0 28 0
[pid=26125] ppid=26122 vsize=79708 CPUtime=11.65
/proc/26125/stat : 26125 (bmo-pblex32) R 26122 26122 25521 34816 25544 4202496 26798 0 0 0 1062 103 0 0 25 0 1 0 899870765 81620992 19616 1283457024 134512640 135887319 4294343136 18446744073709551615 134615491 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26125/statm: 19927 19616 144 336 0 19589 0
Current children cumulated CPU time (s) 14.23
Current children cumulated vsize (KiB) 82276

[startup+15.2096 s]
/proc/loadavg: 1.09 0.91 0.49 2/39 26125
/proc/meminfo: memFree=340344/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=2.58
/proc/26122/stat : 26122 (cudf2pbo4user-1) S 26121 26122 25521 34816 25544 4202496 401 14884 0 0 0 0 204 54 20 0 1 0 899870500 2629632 281 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26122/statm: 642 281 241 194 0 28 0
[pid=26125] ppid=26122 vsize=80120 CPUtime=12.44
/proc/26125/stat : 26125 (bmo-pblex32) R 26122 26122 25521 34816 25544 4202496 26928 0 0 0 1137 107 0 0 25 0 1 0 899870765 82042880 19721 1283457024 134512640 135887319 4294343136 18446744073709551615 134598364 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26125/statm: 20030 19721 144 336 0 19692 0
Current children cumulated CPU time (s) 15.02
Current children cumulated vsize (KiB) 82688

[startup+16.0098 s]
/proc/loadavg: 1.09 0.91 0.49 2/39 26125
/proc/meminfo: memFree=339724/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=2.58
/proc/26122/stat : 26122 (cudf2pbo4user-1) S 26121 26122 25521 34816 25544 4202496 401 14884 0 0 0 0 204 54 20 0 1 0 899870500 2629632 281 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26122/statm: 642 281 241 194 0 28 0
[pid=26125] ppid=26122 vsize=80528 CPUtime=13.24
/proc/26125/stat : 26125 (bmo-pblex32) R 26122 26122 25521 34816 25544 4202496 27059 0 0 0 1216 108 0 0 25 0 1 0 899870765 82460672 19828 1283457024 134512640 135887319 4294343136 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26125/statm: 20132 19828 144 336 0 19794 0
Current children cumulated CPU time (s) 15.82
Current children cumulated vsize (KiB) 83096

[startup+16.2098 s]
/proc/loadavg: 1.09 0.91 0.49 2/39 26125
/proc/meminfo: memFree=339724/1048576 swapFree=2095372/2097144
[pid=26122] ppid=26121 vsize=2568 CPUtime=15.98
/proc/26122/stat : 26122 (cudf2pbo4user-1) R 26121 26122 25521 34816 25544 4202496 420 41973 0 0 0 0 1433 165 18 0 1 0 899870500 2629632 281 1283457024 134512640 135304128 4287097392 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/26122/statm: 642 281 241 194 0 28 0
Current children cumulated CPU time (s) 15.98
Current children cumulated vsize (KiB) 2568

Child status: 0
Real time (s): 16.2667
CPU time (s): 16.097
CPU user time (s): 14.4249
CPU system time (s): 1.6721
CPU usage (%): 98.9568
Max. virtual memory (cumulated for all children) (KiB): 83236

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 14.4249
system time used= 1.6721
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 44750
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 30
involuntary context switches= 2475

runsolver used 0 second user time and 0 second system time

The end