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/201012081719/cudf2pbo4trendy-1.0/3e4f8550-0b33-11df-942d-00163e1d94dc.cudf.debian-dudf.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/debian-dudf//3e4f8550-0b33-11df-942d-00163e1d94dc.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/3e4f8550-0b33-11df-942d-00163e1d94dc.cudf.debian-dudf.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: 0.88 0.94 0.90 4/39 11221
/proc/meminfo: memFree=57112/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=0
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 893473916 2633728 279 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 279 238 194 0 29 0
[pid=11221] ppid=11220 vsize=2048 CPUtime=0.01
/proc/11221/stat : 11221 (cudf_msu32) R 11220 11220 9023 34817 9081 4202496 324 0 0 0 1 0 0 0 25 0 1 0 893473916 2097152 216 1283457024 134512640 136125367 4293515536 18446744073709551615 134717740 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11221/statm: 512 216 141 394 0 116 0

[startup+0.217507 s]
/proc/loadavg: 0.88 0.94 0.90 4/39 11221
/proc/meminfo: memFree=57112/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=0
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 893473916 2633728 279 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 279 238 194 0 29 0
[pid=11221] ppid=11220 vsize=10184 CPUtime=0.21
/proc/11221/stat : 11221 (cudf_msu32) R 11220 11220 9023 34817 9081 4202496 2344 0 0 0 21 0 0 0 25 0 1 0 893473916 10428416 2236 1283457024 134512640 136125367 4293515536 18446744073709551615 134717695 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11221/statm: 2546 2236 141 394 0 2150 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12756

[startup+0.307518 s]
/proc/loadavg: 0.88 0.94 0.90 4/39 11221
/proc/meminfo: memFree=57112/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=0
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 893473916 2633728 279 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 279 238 194 0 29 0
[pid=11221] ppid=11220 vsize=13152 CPUtime=0.3
/proc/11221/stat : 11221 (cudf_msu32) R 11220 11220 9023 34817 9081 4202496 3082 0 0 0 29 1 0 0 25 0 1 0 893473916 13467648 2974 1283457024 134512640 136125367 4293515536 18446744073709551615 134717794 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11221/statm: 3288 2974 142 394 0 2892 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15724

[startup+0.407535 s]
/proc/loadavg: 0.88 0.94 0.90 4/39 11221
/proc/meminfo: memFree=57112/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=0
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 893473916 2633728 279 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 279 238 194 0 29 0
[pid=11221] ppid=11220 vsize=16056 CPUtime=0.4
/proc/11221/stat : 11221 (cudf_msu32) R 11220 11220 9023 34817 9081 4202496 3829 0 0 0 39 1 0 0 25 0 1 0 893473916 16441344 3721 1283457024 134512640 136125367 4293515536 18446744073709551615 134717802 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11221/statm: 4014 3721 142 394 0 3618 0
Current children cumulated CPU time (s) 0.4
Current children cumulated vsize (KiB) 18628

[startup+0.707579 s]
/proc/loadavg: 0.88 0.94 0.90 4/39 11221
/proc/meminfo: memFree=57112/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=0
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 893473916 2633728 279 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 279 238 194 0 29 0
[pid=11221] ppid=11220 vsize=24184 CPUtime=0.7
/proc/11221/stat : 11221 (cudf_msu32) R 11220 11220 9023 34817 9081 4202496 5842 0 0 0 68 2 0 0 25 0 1 0 893473916 24764416 5734 1283457024 134512640 136125367 4293515536 18446744073709551615 134717779 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11221/statm: 6046 5734 142 394 0 5650 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 26756

[startup+1.50773 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 11222
/proc/meminfo: memFree=23464/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=0
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 893473916 2633728 279 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 279 238 194 0 29 0
[pid=11221] ppid=11220 vsize=50024 CPUtime=1.51
/proc/11221/stat : 11221 (cudf_msu32) R 11220 11220 9023 34817 9081 4202496 12716 0 0 0 142 9 0 0 25 0 1 0 893473916 51224576 12215 1283457024 134512640 136125367 4293515536 18446744073709551615 134623624 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11221/statm: 12506 12215 160 394 0 12110 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 52596

[startup+3.10797 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 11222
/proc/meminfo: memFree=5156/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=2.43
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 403 14005 0 0 0 0 193 50 20 0 1 0 893473916 2633728 282 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 282 241 194 0 29 0
Current children cumulated CPU time (s) 2.43
Current children cumulated vsize (KiB) 2572
heavy processes:

[startup+6.30839 s]
/proc/loadavg: 0.89 0.94 0.91 2/40 11223
/proc/meminfo: memFree=28676/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=2.43
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 403 14005 0 0 0 0 193 50 20 0 1 0 893473916 2633728 282 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 282 241 194 0 29 0
[pid=11223] ppid=11220 vsize=33540 CPUtime=3.88
/proc/11223/stat : 11223 (bmo-pblex32) R 11220 11220 9023 34817 9081 4202496 8779 0 0 0 256 132 0 0 25 0 1 0 893474159 34344960 7824 1283457024 134512640 135887319 4286638720 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11223/statm: 8385 7824 138 336 0 8047 0
Current children cumulated CPU time (s) 6.31
Current children cumulated vsize (KiB) 36112

[startup+12.7104 s]
/proc/loadavg: 0.90 0.94 0.91 2/40 11223
/proc/meminfo: memFree=27808/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=2.43
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 403 14005 0 0 0 0 193 50 20 0 1 0 893473916 2633728 282 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 282 241 194 0 29 0
[pid=11223] ppid=11220 vsize=34448 CPUtime=10.27
/proc/11223/stat : 11223 (bmo-pblex32) R 11220 11220 9023 34817 9081 4202496 9049 0 0 0 730 297 0 0 25 0 1 0 893474159 35274752 8064 1283457024 134512640 135887319 4286638720 18446744073709551615 134624330 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11223/statm: 8612 8064 138 336 0 8274 0
Current children cumulated CPU time (s) 12.7
Current children cumulated vsize (KiB) 37020

[startup+25.5135 s]
/proc/loadavg: 0.92 0.95 0.91 2/40 11223
/proc/meminfo: memFree=25204/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=2.43
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 403 14005 0 0 0 0 193 50 20 0 1 0 893473916 2633728 282 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 282 241 194 0 29 0
[pid=11223] ppid=11220 vsize=42980 CPUtime=23.05
/proc/11223/stat : 11223 (bmo-pblex32) R 11220 11220 9023 34817 9081 4202496 11560 0 0 0 1737 568 0 0 25 0 1 0 893474159 44011520 9984 1283457024 134512640 135887319 4286638720 18446744073709551615 135315584 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11223/statm: 10745 9984 143 336 0 10407 0
Current children cumulated CPU time (s) 25.48
Current children cumulated vsize (KiB) 45552

[startup+51.1102 s]
/proc/loadavg: 0.95 0.95 0.91 2/40 11223
/proc/meminfo: memFree=5732/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=2.43
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 403 14005 0 0 0 0 193 50 20 0 1 0 893473916 2633728 282 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 282 241 194 0 29 0
[pid=11223] ppid=11220 vsize=72908 CPUtime=48.54
/proc/11223/stat : 11223 (bmo-pblex32) R 11220 11220 9023 34817 9081 4202496 24599 0 0 0 3796 1058 0 0 25 0 1 0 893474159 74657792 17848 1283457024 134512640 135887319 4286638720 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11223/statm: 18227 17848 144 336 0 17889 0
Current children cumulated CPU time (s) 50.97
Current children cumulated vsize (KiB) 75480

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

[startup+51.3102 s]
/proc/loadavg: 0.95 0.95 0.91 2/40 11223
/proc/meminfo: memFree=5732/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=2.43
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 403 14005 0 0 0 0 193 50 20 0 1 0 893473916 2633728 282 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 282 241 194 0 29 0
[pid=11223] ppid=11220 vsize=72908 CPUtime=48.73
/proc/11223/stat : 11223 (bmo-pblex32) R 11220 11220 9023 34817 9081 4202496 24619 0 0 0 3813 1060 0 0 25 0 1 0 893474159 74657792 17868 1283457024 134512640 135887319 4286638720 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11223/statm: 18227 17868 144 336 0 17889 0
Current children cumulated CPU time (s) 51.16
Current children cumulated vsize (KiB) 75480

[startup+54.5112 s]
/proc/loadavg: 0.95 0.95 0.91 2/40 11223
/proc/meminfo: memFree=5632/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=2.43
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 403 14005 0 0 0 0 193 50 20 0 1 0 893473916 2633728 282 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 282 241 194 0 29 0
[pid=11223] ppid=11220 vsize=74116 CPUtime=51.94
/proc/11223/stat : 11223 (bmo-pblex32) R 11220 11220 9023 34817 9081 4202496 24926 0 0 0 4101 1093 0 0 25 0 1 0 893474159 75894784 18175 1283457024 134512640 135887319 4286638720 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11223/statm: 18529 18175 144 336 0 18191 0
Current children cumulated CPU time (s) 54.37
Current children cumulated vsize (KiB) 76688

[startup+57.7123 s]
/proc/loadavg: 0.95 0.95 0.91 2/40 11223
/proc/meminfo: memFree=5468/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=2.43
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 403 14005 0 0 0 0 193 50 20 0 1 0 893473916 2633728 282 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 282 241 194 0 29 0
[pid=11223] ppid=11220 vsize=75456 CPUtime=55.13
/proc/11223/stat : 11223 (bmo-pblex32) R 11220 11220 9023 34817 9081 4202496 25242 0 0 0 4396 1117 0 0 25 0 1 0 893474159 77266944 18491 1283457024 134512640 135887319 4286638720 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11223/statm: 18864 18491 144 336 0 18526 0
Current children cumulated CPU time (s) 57.56
Current children cumulated vsize (KiB) 78028

[startup+58.5126 s]
/proc/loadavg: 0.95 0.95 0.91 2/40 11223
/proc/meminfo: memFree=6236/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=2.43
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 403 14005 0 0 0 0 193 50 20 0 1 0 893473916 2633728 282 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 282 241 194 0 29 0
[pid=11223] ppid=11220 vsize=75724 CPUtime=55.92
/proc/11223/stat : 11223 (bmo-pblex32) R 11220 11220 9023 34817 9081 4202496 25323 0 0 0 4463 1129 0 0 25 0 1 0 893474159 77541376 18572 1283457024 134512640 135887319 4286638720 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11223/statm: 18931 18572 144 336 0 18593 0
Current children cumulated CPU time (s) 58.35
Current children cumulated vsize (KiB) 78296

[startup+58.9127 s]
/proc/loadavg: 0.95 0.95 0.91 2/40 11223
/proc/meminfo: memFree=6236/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=2.43
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 403 14005 0 0 0 0 193 50 20 0 1 0 893473916 2633728 282 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 282 241 194 0 29 0
[pid=11223] ppid=11220 vsize=75860 CPUtime=56.33
/proc/11223/stat : 11223 (bmo-pblex32) R 11220 11220 9023 34817 9081 4202496 25364 0 0 0 4501 1132 0 0 25 0 1 0 893474159 77680640 18611 1283457024 134512640 135887319 4286638720 18446744073709551615 134603584 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11223/statm: 18965 18611 144 336 0 18627 0
Current children cumulated CPU time (s) 58.76
Current children cumulated vsize (KiB) 78432

[startup+59.3128 s]
/proc/loadavg: 0.95 0.95 0.91 2/40 11223
/proc/meminfo: memFree=6236/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=2.43
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 403 14005 0 0 0 0 193 50 20 0 1 0 893473916 2633728 282 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 282 241 194 0 29 0
[pid=11223] ppid=11220 vsize=75992 CPUtime=56.73
/proc/11223/stat : 11223 (bmo-pblex32) R 11220 11220 9023 34817 9081 4202496 25383 0 0 0 4541 1132 0 0 25 0 1 0 893474159 77815808 18625 1283457024 134512640 135887319 4286638720 18446744073709551615 135286965 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11223/statm: 18998 18625 145 336 0 18660 0
Current children cumulated CPU time (s) 59.16
Current children cumulated vsize (KiB) 78564

[startup+59.4028 s]
/proc/loadavg: 0.95 0.95 0.91 2/40 11223
/proc/meminfo: memFree=6236/1048576 swapFree=2095372/2097144
[pid=11220] ppid=11219 vsize=2572 CPUtime=59.17
/proc/11220/stat : 11220 (cudf2pbo4trendy) S 11219 11220 9023 34817 9081 4202496 434 39391 0 0 0 0 4734 1183 18 0 1 0 893473916 2633728 282 1283457024 134512640 135304128 4287955776 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11220/statm: 643 282 241 194 0 29 0
Current children cumulated CPU time (s) 59.17
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 59.4342
CPU time (s): 59.2877
CPU user time (s): 47.435
CPU system time (s): 11.8527
CPU usage (%): 99.7535
Max. virtual memory (cumulated for all children) (KiB): 78564

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 47.435
system time used= 11.8527
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 42089
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= 21
involuntary context switches= 7356

runsolver used 0 second user time and 0 second system time

The end