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/randd8bf6a.cudf.difficult.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/difficult//randd8bf6a.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/randd8bf6a.cudf.difficult.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.87 0.94 0.90 4/35 14226
/proc/meminfo: memFree=33692/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=0
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894765053 2629632 278 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 278 238 194 0 28 0
[pid=14226] ppid=14225 vsize=2052 CPUtime=0
/proc/14226/stat : 14226 (cudf_msu32) R 14225 14225 9023 34817 9081 4202496 316 0 0 0 0 0 0 0 25 0 1 0 894765053 2101248 209 1283457024 134512640 136125367 4290135536 18446744073709551615 135528842 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/14226/statm: 513 209 141 394 0 117 0

[startup+0.115789 s]
/proc/loadavg: 0.87 0.94 0.90 4/35 14226
/proc/meminfo: memFree=33692/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=0
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894765053 2629632 278 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 278 238 194 0 28 0
[pid=14226] ppid=14225 vsize=6936 CPUtime=0.11
/proc/14226/stat : 14226 (cudf_msu32) R 14225 14225 9023 34817 9081 4202496 1543 0 0 0 11 0 0 0 25 0 1 0 894765053 7102464 1436 1283457024 134512640 136125367 4290135536 18446744073709551615 134717966 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/14226/statm: 1734 1436 142 394 0 1338 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 9504

[startup+0.20582 s]
/proc/loadavg: 0.87 0.94 0.90 4/35 14226
/proc/meminfo: memFree=33692/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=0
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894765053 2629632 278 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 278 238 194 0 28 0
[pid=14226] ppid=14225 vsize=10576 CPUtime=0.2
/proc/14226/stat : 14226 (cudf_msu32) R 14225 14225 9023 34817 9081 4202496 2444 0 0 0 20 0 0 0 25 0 1 0 894765053 10829824 2337 1283457024 134512640 136125367 4290135536 18446744073709551615 134728315 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/14226/statm: 2644 2337 143 394 0 2248 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13144

[startup+0.305833 s]
/proc/loadavg: 0.87 0.94 0.90 4/35 14226
/proc/meminfo: memFree=33692/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=0
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894765053 2629632 278 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 278 238 194 0 28 0
[pid=14226] ppid=14225 vsize=14140 CPUtime=0.3
/proc/14226/stat : 14226 (cudf_msu32) R 14225 14225 9023 34817 9081 4202496 3344 0 0 0 30 0 0 0 25 0 1 0 894765053 14479360 3237 1283457024 134512640 136125367 4290135536 18446744073709551615 135176438 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/14226/statm: 3535 3237 143 394 0 3139 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16708

[startup+0.705917 s]
/proc/loadavg: 0.87 0.94 0.90 4/35 14226
/proc/meminfo: memFree=33692/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=0
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894765053 2629632 278 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 278 238 194 0 28 0
[pid=14226] ppid=14225 vsize=26480 CPUtime=0.7
/proc/14226/stat : 14226 (cudf_msu32) R 14225 14225 9023 34817 9081 4202496 6437 0 0 0 68 2 0 0 25 0 1 0 894765053 27115520 6330 1283457024 134512640 136125367 4290135536 18446744073709551615 135549054 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/14226/statm: 6620 6330 143 394 0 6224 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 29048

[startup+1.50586 s]
/proc/loadavg: 0.87 0.94 0.90 2/36 14227
/proc/meminfo: memFree=5356/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=1.17
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 402 8366 0 0 0 0 96 21 20 0 1 0 894765053 2629632 281 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 281 241 194 0 28 0
Current children cumulated CPU time (s) 1.17
Current children cumulated vsize (KiB) 2568

[startup+3.11348 s]
/proc/loadavg: 0.87 0.94 0.90 2/36 14228
/proc/meminfo: memFree=27576/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=1.17
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 402 8366 0 0 0 0 96 21 20 0 1 0 894765053 2629632 281 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 281 241 194 0 28 0
[pid=14228] ppid=14225 vsize=16468 CPUtime=1.87
/proc/14228/stat : 14228 (bmo-pblex32) R 14225 14225 9023 34817 9081 4202496 5089 0 0 0 116 71 0 0 25 0 1 0 894765171 16863232 3824 1283457024 134512640 135887319 4292177904 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14228/statm: 4117 3824 144 336 0 3779 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 19036

[startup+6.3042 s]
/proc/loadavg: 0.88 0.94 0.90 2/36 14228
/proc/meminfo: memFree=15432/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=1.17
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 402 8366 0 0 0 0 96 21 20 0 1 0 894765053 2629632 281 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 281 241 194 0 28 0
[pid=14228] ppid=14225 vsize=25020 CPUtime=5.05
/proc/14228/stat : 14228 (bmo-pblex32) R 14225 14225 9023 34817 9081 4202496 8583 0 0 0 384 121 0 0 25 0 1 0 894765171 25620480 5969 1283457024 134512640 135887319 4292177904 18446744073709551615 134526502 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14228/statm: 6255 5969 144 336 0 5917 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 27588

[startup+12.7055 s]
/proc/loadavg: 0.89 0.94 0.90 2/36 14228
/proc/meminfo: memFree=14564/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=1.17
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 402 8366 0 0 0 0 96 21 20 0 1 0 894765053 2629632 281 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 281 241 194 0 28 0
[pid=14228] ppid=14225 vsize=25820 CPUtime=11.44
/proc/14228/stat : 14228 (bmo-pblex32) R 14225 14225 9023 34817 9081 4202496 8820 0 0 0 1020 124 0 0 25 0 1 0 894765171 26439680 6188 1283457024 134512640 135887319 4292177904 18446744073709551615 134525472 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14228/statm: 6455 6188 144 336 0 6117 0
Current children cumulated CPU time (s) 12.61
Current children cumulated vsize (KiB) 28388

[startup+25.5081 s]
/proc/loadavg: 0.91 0.94 0.90 2/36 14228
/proc/meminfo: memFree=12952/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=1.17
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 402 8366 0 0 0 0 96 21 20 0 1 0 894765053 2629632 281 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 281 241 194 0 28 0
[pid=14228] ppid=14225 vsize=27472 CPUtime=24.24
/proc/14228/stat : 14228 (bmo-pblex32) R 14225 14225 9023 34817 9081 4202496 9266 0 0 0 2298 126 0 0 25 0 1 0 894765171 28131328 6577 1283457024 134512640 135887319 4292177904 18446744073709551615 134614940 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14228/statm: 6868 6577 144 336 0 6530 0
Current children cumulated CPU time (s) 25.41
Current children cumulated vsize (KiB) 30040

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

[startup+25.6081 s]
/proc/loadavg: 0.91 0.94 0.90 2/36 14228
/proc/meminfo: memFree=12952/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=1.17
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 402 8366 0 0 0 0 96 21 20 0 1 0 894765053 2629632 281 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 281 241 194 0 28 0
[pid=14228] ppid=14225 vsize=27472 CPUtime=24.34
/proc/14228/stat : 14228 (bmo-pblex32) R 14225 14225 9023 34817 9081 4202496 9268 0 0 0 2308 126 0 0 25 0 1 0 894765171 28131328 6579 1283457024 134512640 135887319 4292177904 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14228/statm: 6868 6579 144 336 0 6530 0
Current children cumulated CPU time (s) 25.51
Current children cumulated vsize (KiB) 30040

[startup+27.2084 s]
/proc/loadavg: 0.91 0.94 0.90 2/36 14228
/proc/meminfo: memFree=12828/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=1.17
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 402 8366 0 0 0 0 96 21 20 0 1 0 894765053 2629632 281 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 281 241 194 0 28 0
[pid=14228] ppid=14225 vsize=27604 CPUtime=25.94
/proc/14228/stat : 14228 (bmo-pblex32) R 14225 14225 9023 34817 9081 4202496 9319 0 0 0 2467 127 0 0 25 0 1 0 894765171 28266496 6630 1283457024 134512640 135887319 4292177904 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14228/statm: 6901 6630 144 336 0 6563 0
Current children cumulated CPU time (s) 27.11
Current children cumulated vsize (KiB) 30172

[startup+28.0086 s]
/proc/loadavg: 0.91 0.94 0.90 2/36 14228
/proc/meminfo: memFree=12704/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=1.17
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 402 8366 0 0 0 0 96 21 20 0 1 0 894765053 2629632 281 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 281 241 194 0 28 0
[pid=14228] ppid=14225 vsize=27740 CPUtime=26.72
/proc/14228/stat : 14228 (bmo-pblex32) R 14225 14225 9023 34817 9081 4202496 9351 0 0 0 2545 127 0 0 25 0 1 0 894765171 28405760 6655 1283457024 134512640 135887319 4292177904 18446744073709551615 134615136 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14228/statm: 6935 6655 144 336 0 6597 0
Current children cumulated CPU time (s) 27.89
Current children cumulated vsize (KiB) 30308

[startup+28.4087 s]
/proc/loadavg: 0.91 0.94 0.90 2/36 14228
/proc/meminfo: memFree=12704/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=1.17
/proc/14225/stat : 14225 (cudf2pbo4trendy) S 14224 14225 9023 34817 9081 4202496 402 8366 0 0 0 0 96 21 20 0 1 0 894765053 2629632 281 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14225/statm: 642 281 241 194 0 28 0
[pid=14228] ppid=14225 vsize=27740 CPUtime=27.12
/proc/14228/stat : 14228 (bmo-pblex32) R 14225 14225 9023 34817 9081 4202496 9361 0 0 0 2585 127 0 0 25 0 1 0 894765171 28405760 6665 1283457024 134512640 135887319 4292177904 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14228/statm: 6935 6665 144 336 0 6597 0
Current children cumulated CPU time (s) 28.29
Current children cumulated vsize (KiB) 30308

[startup+28.6087 s]
/proc/loadavg: 0.91 0.94 0.90 3/37 14230
/proc/meminfo: memFree=37984/1048576 swapFree=2095372/2097144
[pid=14225] ppid=14224 vsize=2568 CPUtime=28.48
/proc/14225/stat : 14225 (cudf2pbo4trendy) R 14224 14225 9023 34817 9081 4202496 421 17754 0 0 0 0 2700 148 18 0 1 0 894765053 2629632 281 1283457024 134512640 135304128 4294793712 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/14225/statm: 642 281 241 194 0 28 0
[pid=14229] ppid=14225 vsize=0 CPUtime=0
/proc/14229/stat : 14229 (grep) Z 14225 14225 9023 34817 9081 4202508 321 0 0 0 0 0 0 0 18 0 1 0 894767913 0 0 1283457024 0 0 0 0 0 0 0 0 0 18446744071564254338 0 0 17 0 0 0 0
/proc/14229/statm: 0 0 0 0 0 0 0
[pid=14230] ppid=14225 vsize=5788 CPUtime=0
/proc/14230/stat : 14230 (sc.py) R 14225 14225 9023 34817 9081 4194304 258 0 0 0 0 0 0 0 18 0 1 0 894767913 5926912 133 1283457024 134512640 136476992 4294203872 18446744073709551615 4160382786 0 0 0 0 0 0 0 17 0 0 0 0
/proc/14230/statm: 1447 133 91 480 0 27 0
Current children cumulated CPU time (s) 28.48
Current children cumulated vsize (KiB) 8356

Child status: 0
Real time (s): 28.658
CPU time (s): 28.5378
CPU user time (s): 27.0497
CPU system time (s): 1.48809
CPU usage (%): 99.5805
Max. virtual memory (cumulated for all children) (KiB): 36636

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 27.0497
system time used= 1.48809
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 19882
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= 9
involuntary context switches= 2414

runsolver used 0 second user time and 0 second system time

The end