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/cudf2pbo4paranoid-1.0/rand332173.cudf.impossible.log.runsolver ./cudf2pbo4paranoid-1.0 /home/misc2010/data/2010/impossible//rand332173.cudf /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/rand332173.cudf.impossible.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.84 0.93 0.90 3/39 9719
/proc/meminfo: memFree=56956/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=0
/proc/9718/stat : 9718 (cudf2pbo4parano) S 9717 9718 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892493669 2629632 278 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9718/statm: 642 278 238 194 0 28 0
[pid=9719] ppid=9718 vsize=1916 CPUtime=0
/proc/9719/stat : 9719 (cudf_msu32) D 9718 9718 9023 34817 9081 4202496 264 0 0 0 0 0 0 0 18 0 1 0 892493669 1961984 157 1283457024 134512640 136125367 4286894800 18446744073709551615 135594526 0 0 0 25121 18446744071564332000 0 0 17 0 0 0 0
/proc/9719/statm: 479 157 133 394 0 83 0

[startup+0.160776 s]
/proc/loadavg: 0.84 0.93 0.90 3/39 9719
/proc/meminfo: memFree=56956/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=0
/proc/9718/stat : 9718 (cudf2pbo4parano) S 9717 9718 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892493669 2629632 278 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9718/statm: 642 278 238 194 0 28 0
[pid=9719] ppid=9718 vsize=7784 CPUtime=0.13
/proc/9719/stat : 9719 (cudf_msu32) R 9718 9718 9023 34817 9081 4202496 1759 0 0 0 13 0 0 0 25 0 1 0 892493669 7970816 1652 1283457024 134512640 136125367 4286894800 18446744073709551615 134717628 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9719/statm: 1946 1652 143 394 0 1550 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 10352

[startup+0.209051 s]
/proc/loadavg: 0.84 0.93 0.90 3/39 9719
/proc/meminfo: memFree=56956/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=0
/proc/9718/stat : 9718 (cudf2pbo4parano) S 9717 9718 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892493669 2629632 278 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9718/statm: 642 278 238 194 0 28 0
[pid=9719] ppid=9718 vsize=9500 CPUtime=0.16
/proc/9719/stat : 9719 (cudf_msu32) R 9718 9718 9023 34817 9081 4202496 2190 0 0 0 16 0 0 0 25 0 1 0 892493669 9728000 2083 1283457024 134512640 136125367 4286894800 18446744073709551615 135549054 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9719/statm: 2375 2083 143 394 0 1979 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 12068

[startup+0.304787 s]
/proc/loadavg: 0.84 0.93 0.90 3/39 9719
/proc/meminfo: memFree=56956/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=0
/proc/9718/stat : 9718 (cudf2pbo4parano) S 9717 9718 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892493669 2629632 278 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9718/statm: 642 278 238 194 0 28 0
[pid=9719] ppid=9718 vsize=12956 CPUtime=0.25
/proc/9719/stat : 9719 (cudf_msu32) R 9718 9718 9023 34817 9081 4202496 3040 0 0 0 25 0 0 0 25 0 1 0 892493669 13266944 2933 1283457024 134512640 136125367 4286894800 18446744073709551615 134717918 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9719/statm: 3239 2933 144 394 0 2843 0
Current children cumulated CPU time (s) 0.25
Current children cumulated vsize (KiB) 15524

[startup+0.704802 s]
/proc/loadavg: 0.84 0.93 0.90 3/39 9719
/proc/meminfo: memFree=56956/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=0
/proc/9718/stat : 9718 (cudf2pbo4parano) S 9717 9718 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892493669 2629632 278 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9718/statm: 642 278 238 194 0 28 0
[pid=9719] ppid=9718 vsize=24900 CPUtime=0.6
/proc/9719/stat : 9719 (cudf_msu32) R 9718 9718 9023 34817 9081 4202496 6027 0 0 0 58 2 0 0 25 0 1 0 892493669 25497600 5920 1283457024 134512640 136125367 4286894800 18446744073709551615 134717925 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9719/statm: 6225 5920 144 394 0 5829 0
Current children cumulated CPU time (s) 0.6
Current children cumulated vsize (KiB) 27468

[startup+1.50485 s]
/proc/loadavg: 0.85 0.93 0.90 2/40 9720
/proc/meminfo: memFree=6076/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=0
/proc/9718/stat : 9718 (cudf2pbo4parano) S 9717 9718 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892493669 2629632 278 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9718/statm: 642 278 238 194 0 28 0
[pid=9719] ppid=9718 vsize=45024 CPUtime=1.26
/proc/9719/stat : 9719 (cudf_msu32) R 9718 9718 9023 34817 9081 4202496 11115 0 0 0 124 2 0 0 25 0 1 0 892493669 46104576 10959 1283457024 134512640 136125367 4286894800 18446744073709551615 134717792 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9719/statm: 11256 10959 144 394 0 10860 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 47592

[startup+3.10542 s]
/proc/loadavg: 0.85 0.93 0.90 2/40 9720
/proc/meminfo: memFree=5384/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=2.1
/proc/9718/stat : 9718 (cudf2pbo4parano) S 9717 9718 9023 34817 9081 4202496 401 14840 0 0 0 0 174 36 20 0 1 0 892493669 2629632 281 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9718/statm: 642 281 241 194 0 28 0
Current children cumulated CPU time (s) 2.1
Current children cumulated vsize (KiB) 2568
heavy processes:

[startup+6.3085 s]
/proc/loadavg: 0.85 0.93 0.90 2/40 9721
/proc/meminfo: memFree=39504/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=2.1
/proc/9718/stat : 9718 (cudf2pbo4parano) S 9717 9718 9023 34817 9081 4202496 401 14840 0 0 0 0 174 36 20 0 1 0 892493669 2629632 281 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9718/statm: 642 281 241 194 0 28 0
[pid=9721] ppid=9718 vsize=26880 CPUtime=3.83
/proc/9721/stat : 9721 (bmo-pblex32) R 9718 9718 9023 34817 9081 4202496 7938 0 0 0 306 77 0 0 25 0 1 0 892493905 27525120 6420 1283457024 134512640 135887319 4288072704 18446744073709551615 134598364 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9721/statm: 6720 6420 144 336 0 6382 0
Current children cumulated CPU time (s) 5.93
Current children cumulated vsize (KiB) 29448

[startup+12.7106 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 9721
/proc/meminfo: memFree=35288/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=2.1
/proc/9718/stat : 9718 (cudf2pbo4parano) S 9717 9718 9023 34817 9081 4202496 401 14840 0 0 0 0 174 36 20 0 1 0 892493669 2629632 281 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9718/statm: 642 281 241 194 0 28 0
[pid=9721] ppid=9718 vsize=31132 CPUtime=10.18
/proc/9721/stat : 9721 (bmo-pblex32) R 9718 9718 9023 34817 9081 4202496 9039 0 0 0 835 183 0 0 25 0 1 0 892493905 31879168 7486 1283457024 134512640 135887319 4288072704 18446744073709551615 134614896 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9721/statm: 7783 7486 144 336 0 7445 0
Current children cumulated CPU time (s) 12.28
Current children cumulated vsize (KiB) 33700

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

[startup+12.8106 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 9721
/proc/meminfo: memFree=35288/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=2.1
/proc/9718/stat : 9718 (cudf2pbo4parano) S 9717 9718 9023 34817 9081 4202496 401 14840 0 0 0 0 174 36 20 0 1 0 892493669 2629632 281 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9718/statm: 642 281 241 194 0 28 0
[pid=9721] ppid=9718 vsize=31132 CPUtime=10.28
/proc/9721/stat : 9721 (bmo-pblex32) R 9718 9718 9023 34817 9081 4202496 9039 0 0 0 845 183 0 0 25 0 1 0 892493905 31879168 7486 1283457024 134512640 135887319 4288072704 18446744073709551615 134615440 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9721/statm: 7783 7486 144 336 0 7445 0
Current children cumulated CPU time (s) 12.38
Current children cumulated vsize (KiB) 33700

[startup+14.4109 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 9721
/proc/meminfo: memFree=34916/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=2.1
/proc/9718/stat : 9718 (cudf2pbo4parano) S 9717 9718 9023 34817 9081 4202496 401 14840 0 0 0 0 174 36 20 0 1 0 892493669 2629632 281 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9718/statm: 642 281 241 194 0 28 0
[pid=9721] ppid=9718 vsize=31396 CPUtime=11.88
/proc/9721/stat : 9721 (bmo-pblex32) R 9718 9718 9023 34817 9081 4202496 9091 0 0 0 1005 183 0 0 25 0 1 0 892493905 32149504 7532 1283457024 134512640 135887319 4288072704 18446744073709551615 134526961 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9721/statm: 7849 7532 144 336 0 7511 0
Current children cumulated CPU time (s) 13.98
Current children cumulated vsize (KiB) 33964

[startup+14.811 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 9721
/proc/meminfo: memFree=34916/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=2.1
/proc/9718/stat : 9718 (cudf2pbo4parano) S 9717 9718 9023 34817 9081 4202496 401 14840 0 0 0 0 174 36 20 0 1 0 892493669 2629632 281 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9718/statm: 642 281 241 194 0 28 0
[pid=9721] ppid=9718 vsize=31396 CPUtime=12.27
/proc/9721/stat : 9721 (bmo-pblex32) R 9718 9718 9023 34817 9081 4202496 9113 0 0 0 1044 183 0 0 25 0 1 0 892493905 32149504 7550 1283457024 134512640 135887319 4288072704 18446744073709551615 134605881 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9721/statm: 7849 7550 144 336 0 7511 0
Current children cumulated CPU time (s) 14.37
Current children cumulated vsize (KiB) 33964

[startup+15.0111 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 9721
/proc/meminfo: memFree=34916/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=2.1
/proc/9718/stat : 9718 (cudf2pbo4parano) S 9717 9718 9023 34817 9081 4202496 401 14840 0 0 0 0 174 36 20 0 1 0 892493669 2629632 281 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9718/statm: 642 281 241 194 0 28 0
[pid=9721] ppid=9718 vsize=31396 CPUtime=12.47
/proc/9721/stat : 9721 (bmo-pblex32) R 9718 9718 9023 34817 9081 4202496 9113 0 0 0 1064 183 0 0 25 0 1 0 892493905 32149504 7550 1283457024 134512640 135887319 4288072704 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9721/statm: 7849 7550 144 336 0 7511 0
Current children cumulated CPU time (s) 14.57
Current children cumulated vsize (KiB) 33964

[startup+15.1111 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 9721
/proc/meminfo: memFree=34916/1048576 swapFree=2095372/2097144
[pid=9718] ppid=9717 vsize=2568 CPUtime=14.63
/proc/9718/stat : 9718 (cudf2pbo4parano) R 9717 9718 9023 34817 9081 4202496 420 23957 0 0 0 0 1242 221 18 0 1 0 892493669 2629632 281 1283457024 134512640 135304128 4286573072 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/9718/statm: 642 281 241 194 0 28 0
Current children cumulated CPU time (s) 14.63
Current children cumulated vsize (KiB) 2568

Child status: 0
Real time (s): 15.1317
CPU time (s): 14.7129
CPU user time (s): 12.4888
CPU system time (s): 2.22414
CPU usage (%): 97.2322
Max. virtual memory (cumulated for all children) (KiB): 62444

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.4888
system time used= 2.22414
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 26347
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= 67
involuntary context switches= 4733

runsolver used 0.012 second user time and 0 second system time

The end