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/201108241238/packup2mp4tr-0.6/ca8f656c-db9e-11df-b9cf-00163e3d3b7c.cudf.dudf-real.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/dudf-real//ca8f656c-db9e-11df-b9cf-00163e3d3b7c.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/ca8f656c-db9e-11df-b9cf-00163e3d3b7c.cudf.dudf-real.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.60 1.28 1.14 3/35 30777
/proc/meminfo: memFree=304792/1048576 swapFree=0/0
[pid=30776] ppid=30775 vsize=2572 CPUtime=0
/proc/30776/stat : 30776 (packup2mp4tr-0.) S 30775 30776 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 5032762 2633728 275 1283457024 134512640 135304128 4291360384 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30776/statm: 643 275 233 194 0 30 0
[pid=30777] ppid=30776 vsize=3712 CPUtime=0
/proc/30777/stat : 30777 (packup) R 30776 30776 1511 34817 1511 4202496 426 0 0 0 0 0 0 0 25 0 1 0 5032762 3801088 355 1283457024 134512640 134752139 4289119280 18446744073709551615 4159286149 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30777/statm: 928 355 286 59 0 92 0

[startup+0.175266 s]
/proc/loadavg: 1.60 1.28 1.14 3/35 30777
/proc/meminfo: memFree=304792/1048576 swapFree=0/0
[pid=30776] ppid=30775 vsize=2572 CPUtime=0
/proc/30776/stat : 30776 (packup2mp4tr-0.) S 30775 30776 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 5032762 2633728 275 1283457024 134512640 135304128 4291360384 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30776/statm: 643 275 233 194 0 30 0
[pid=30777] ppid=30776 vsize=9800 CPUtime=0.17
/proc/30777/stat : 30777 (packup) R 30776 30776 1511 34817 1511 4202496 1938 0 0 0 17 0 0 0 25 0 1 0 5032762 10035200 1867 1283457024 134512640 134752139 4289119280 18446744073709551615 134681674 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30777/statm: 2450 1867 286 59 0 1614 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 12372

[startup+0.215274 s]
/proc/loadavg: 1.60 1.28 1.14 3/35 30777
/proc/meminfo: memFree=304792/1048576 swapFree=0/0
[pid=30776] ppid=30775 vsize=2572 CPUtime=0
/proc/30776/stat : 30776 (packup2mp4tr-0.) S 30775 30776 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 5032762 2633728 275 1283457024 134512640 135304128 4291360384 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30776/statm: 643 275 233 194 0 30 0
[pid=30777] ppid=30776 vsize=10988 CPUtime=0.21
/proc/30777/stat : 30777 (packup) R 30776 30776 1511 34817 1511 4202496 2242 0 0 0 21 0 0 0 25 0 1 0 5032762 11251712 2171 1283457024 134512640 134752139 4289119280 18446744073709551615 134682011 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30777/statm: 2747 2171 286 59 0 1911 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 13560

[startup+0.315296 s]
/proc/loadavg: 1.60 1.28 1.14 3/35 30777
/proc/meminfo: memFree=304792/1048576 swapFree=0/0
[pid=30776] ppid=30775 vsize=2572 CPUtime=0
/proc/30776/stat : 30776 (packup2mp4tr-0.) S 30775 30776 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 5032762 2633728 275 1283457024 134512640 135304128 4291360384 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30776/statm: 643 275 233 194 0 30 0
[pid=30777] ppid=30776 vsize=14088 CPUtime=0.32
/proc/30777/stat : 30777 (packup) R 30776 30776 1511 34817 1511 4202496 3001 0 0 0 30 2 0 0 25 0 1 0 5032762 14426112 2930 1283457024 134512640 134752139 4289119280 18446744073709551615 4157346531 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30777/statm: 3522 2930 286 59 0 2686 0
Current children cumulated CPU time (s) 0.32
Current children cumulated vsize (KiB) 16660

[startup+0.71538 s]
/proc/loadavg: 1.60 1.28 1.14 3/35 30777
/proc/meminfo: memFree=304792/1048576 swapFree=0/0
[pid=30776] ppid=30775 vsize=2572 CPUtime=0
/proc/30776/stat : 30776 (packup2mp4tr-0.) S 30775 30776 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 5032762 2633728 275 1283457024 134512640 135304128 4291360384 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30776/statm: 643 275 233 194 0 30 0
[pid=30777] ppid=30776 vsize=27068 CPUtime=0.71
/proc/30777/stat : 30777 (packup) R 30776 30776 1511 34817 1511 4202496 6292 0 0 0 69 2 0 0 25 0 1 0 5032762 27717632 6221 1283457024 134512640 134752139 4289119280 18446744073709551615 4157344813 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30777/statm: 6767 6221 307 59 0 5931 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 29640

[startup+1.51551 s]
/proc/loadavg: 1.55 1.27 1.14 2/38 30780
/proc/meminfo: memFree=272784/1048576 swapFree=0/0
[pid=30776] ppid=30775 vsize=2572 CPUtime=0
/proc/30776/stat : 30776 (packup2mp4tr-0.) S 30775 30776 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 5032762 2633728 275 1283457024 134512640 135304128 4291360384 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30776/statm: 643 275 233 194 0 30 0
[pid=30777] ppid=30776 vsize=30608 CPUtime=0.94
/proc/30777/stat : 30777 (packup) S 30776 30776 1511 34817 1511 4202496 7170 0 0 0 82 12 0 0 25 0 1 0 5032762 31342592 7098 1283457024 134512640 134752139 4289119280 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30777/statm: 7652 7098 324 59 0 6816 0
[pid=30779] ppid=30777 vsize=1672 CPUtime=0
/proc/30779/stat : 30779 (sh) S 30777 30776 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 25 0 1 0 5032856 1712128 124 1283457024 134512640 134593992 4287193920 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30779/statm: 418 124 108 20 0 45 0
[pid=30780] ppid=30779 vsize=16072 CPUtime=0.57
/proc/30780/stat : 30780 (minisatp_32) R 30779 30776 1511 34817 1511 4202496 3306 0 0 0 53 4 0 0 25 0 1 0 5032857 16457728 2784 1283457024 134512640 135413687 4292765856 18446744073709551615 134988446 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30780/statm: 4018 2784 85 220 0 3796 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 50924

[startup+3.10616 s]
/proc/loadavg: 1.55 1.27 1.14 2/38 30782
/proc/meminfo: memFree=265468/1048576 swapFree=0/0
[pid=30776] ppid=30775 vsize=2572 CPUtime=0
/proc/30776/stat : 30776 (packup2mp4tr-0.) S 30775 30776 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 5032762 2633728 275 1283457024 134512640 135304128 4291360384 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30776/statm: 643 275 233 194 0 30 0
[pid=30777] ppid=30776 vsize=31844 CPUtime=2.8
/proc/30777/stat : 30777 (packup) S 30776 30776 1511 34817 1511 4202496 7788 12160 0 0 102 24 138 16 18 0 1 0 5032762 32608256 7307 1283457024 134512640 134752139 4289119280 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30777/statm: 7961 7307 332 59 0 7125 0
Current children cumulated CPU time (s) 2.8
Current children cumulated vsize (KiB) 34416

[startup+6.30696 s]
/proc/loadavg: 1.55 1.27 1.14 2/38 30786
/proc/meminfo: memFree=269560/1048576 swapFree=0/0
[pid=30776] ppid=30775 vsize=2572 CPUtime=0
/proc/30776/stat : 30776 (packup2mp4tr-0.) S 30775 30776 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 5032762 2633728 275 1283457024 134512640 135304128 4291360384 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30776/statm: 643 275 233 194 0 30 0
[pid=30777] ppid=30776 vsize=31848 CPUtime=5.22
/proc/30777/stat : 30777 (packup) S 30776 30776 1511 34817 1511 4202496 7839 37968 0 0 109 33 344 36 18 0 1 0 5032762 32612352 7308 1283457024 134512640 134752139 4289119280 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30777/statm: 7962 7308 332 59 0 7126 0
[pid=30785] ppid=30777 vsize=1676 CPUtime=0
/proc/30785/stat : 30785 (sh) S 30777 30776 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 5033286 1716224 124 1283457024 134512640 134593992 4290012656 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30785/statm: 419 124 108 20 0 46 0
[pid=30786] ppid=30785 vsize=61488 CPUtime=1.06
/proc/30786/stat : 30786 (minisatp_32) R 30785 30776 1511 34817 1511 4202496 18551 0 0 0 94 12 0 0 24 0 1 0 5033286 62963712 14370 1283457024 134512640 135413687 4294531664 18446744073709551615 134689024 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30786/statm: 15372 14370 95 220 0 15150 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 97584

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

[startup+6.40699 s]
/proc/loadavg: 1.55 1.27 1.14 2/38 30786
/proc/meminfo: memFree=269560/1048576 swapFree=0/0
[pid=30776] ppid=30775 vsize=2572 CPUtime=0
/proc/30776/stat : 30776 (packup2mp4tr-0.) S 30775 30776 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 5032762 2633728 275 1283457024 134512640 135304128 4291360384 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30776/statm: 643 275 233 194 0 30 0
[pid=30777] ppid=30776 vsize=31848 CPUtime=5.22
/proc/30777/stat : 30777 (packup) S 30776 30776 1511 34817 1511 4202496 7839 37968 0 0 109 33 344 36 18 0 1 0 5032762 32612352 7308 1283457024 134512640 134752139 4289119280 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30777/statm: 7962 7308 332 59 0 7126 0
[pid=30785] ppid=30777 vsize=1676 CPUtime=0
/proc/30785/stat : 30785 (sh) S 30777 30776 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 5033286 1716224 124 1283457024 134512640 134593992 4290012656 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30785/statm: 419 124 108 20 0 46 0
[pid=30786] ppid=30785 vsize=62800 CPUtime=1.16
/proc/30786/stat : 30786 (minisatp_32) R 30785 30776 1511 34817 1511 4202496 19089 0 0 0 104 12 0 0 24 0 1 0 5033286 64307200 14701 1283457024 134512640 135413687 4294531664 18446744073709551615 134700055 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30786/statm: 15700 14701 95 220 0 15478 0
Current children cumulated CPU time (s) 6.38
Current children cumulated vsize (KiB) 98896

[startup+8.00731 s]
/proc/loadavg: 1.50 1.27 1.13 2/38 30786
/proc/meminfo: memFree=200004/1048576 swapFree=0/0
[pid=30776] ppid=30775 vsize=2572 CPUtime=0
/proc/30776/stat : 30776 (packup2mp4tr-0.) S 30775 30776 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 5032762 2633728 275 1283457024 134512640 135304128 4291360384 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30776/statm: 643 275 233 194 0 30 0
[pid=30777] ppid=30776 vsize=31848 CPUtime=5.22
/proc/30777/stat : 30777 (packup) S 30776 30776 1511 34817 1511 4202496 7839 37968 0 0 109 33 344 36 18 0 1 0 5032762 32612352 7308 1283457024 134512640 134752139 4289119280 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30777/statm: 7962 7308 332 59 0 7126 0
[pid=30785] ppid=30777 vsize=1676 CPUtime=0
/proc/30785/stat : 30785 (sh) S 30777 30776 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 5033286 1716224 124 1283457024 134512640 134593992 4290012656 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30785/statm: 419 124 108 20 0 46 0
[pid=30786] ppid=30785 vsize=82984 CPUtime=2.75
/proc/30786/stat : 30786 (minisatp_32) R 30785 30776 1511 34817 1511 4202496 29732 0 0 0 262 13 0 0 25 0 1 0 5033286 84975616 18175 1283457024 134512640 135413687 4294531664 18446744073709551615 134962843 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30786/statm: 20746 18175 108 220 0 20524 0
Current children cumulated CPU time (s) 7.97
Current children cumulated vsize (KiB) 119080

[startup+8.40742 s]
/proc/loadavg: 1.50 1.27 1.13 2/38 30786
/proc/meminfo: memFree=200004/1048576 swapFree=0/0
[pid=30776] ppid=30775 vsize=2572 CPUtime=0
/proc/30776/stat : 30776 (packup2mp4tr-0.) S 30775 30776 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 5032762 2633728 275 1283457024 134512640 135304128 4291360384 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30776/statm: 643 275 233 194 0 30 0
[pid=30777] ppid=30776 vsize=31848 CPUtime=5.22
/proc/30777/stat : 30777 (packup) S 30776 30776 1511 34817 1511 4202496 7839 37968 0 0 109 33 344 36 18 0 1 0 5032762 32612352 7308 1283457024 134512640 134752139 4289119280 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30777/statm: 7962 7308 332 59 0 7126 0
[pid=30785] ppid=30777 vsize=1676 CPUtime=0
/proc/30785/stat : 30785 (sh) S 30777 30776 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 5033286 1716224 124 1283457024 134512640 134593992 4290012656 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30785/statm: 419 124 108 20 0 46 0
[pid=30786] ppid=30785 vsize=84116 CPUtime=3.14
/proc/30786/stat : 30786 (minisatp_32) R 30785 30776 1511 34817 1511 4202496 31088 0 0 0 300 14 0 0 25 0 1 0 5033286 86134784 18525 1283457024 134512640 135413687 4294531664 18446744073709551615 134649532 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30786/statm: 21029 18525 110 220 0 20807 0
Current children cumulated CPU time (s) 8.36
Current children cumulated vsize (KiB) 120212

[startup+8.80758 s]
/proc/loadavg: 1.50 1.27 1.13 2/36 30786
/proc/meminfo: memFree=277040/1048576 swapFree=0/0
[pid=30776] ppid=30775 vsize=2572 CPUtime=0
/proc/30776/stat : 30776 (packup2mp4tr-0.) S 30775 30776 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 5032762 2633728 275 1283457024 134512640 135304128 4291360384 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30776/statm: 643 275 233 194 0 30 0
[pid=30777] ppid=30776 vsize=30196 CPUtime=8.79
/proc/30777/stat : 30777 (packup) R 30776 30776 1511 34817 1511 4202496 14233 69222 0 0 116 36 676 51 18 0 1 0 5032762 30920704 7012 1283457024 134512640 134752139 4289119280 18446744073709551615 4157334941 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30777/statm: 7549 7012 345 59 0 6713 0
Current children cumulated CPU time (s) 8.79
Current children cumulated vsize (KiB) 32768

Child status: 0
Real time (s): 8.82497
CPU time (s): 8.80855
CPU user time (s): 7.9325
CPU system time (s): 0.876054
CPU usage (%): 99.814
Max. virtual memory (cumulated for all children) (KiB): 124504

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.9325
system time used= 0.876054
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 84092
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= 22
involuntary context switches= 174

runsolver used 0 second user time and 0 second system time

The end