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/201108251442/packup2mp4pa-0.6/8680dd8a-8600-11e0-b285-00163e1e087d.cudf.dudf-real.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-real//8680dd8a-8600-11e0-b285-00163e1e087d.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/8680dd8a-8600-11e0-b285-00163e1e087d.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.62 1.45 1.31 5/36 25979
/proc/meminfo: memFree=283444/1048576 swapFree=0/0
[pid=25978] ppid=25977 vsize=2572 CPUtime=0
/proc/25978/stat : 25978 (packup2mp4pa-0.) S 25977 25978 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11206926 2633728 275 1283457024 134512640 135304128 4288123760 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/25978/statm: 643 275 233 194 0 30 0
[pid=25979] ppid=25978 vsize=4112 CPUtime=0.01
/proc/25979/stat : 25979 (packup) R 25978 25978 4778 34817 4778 4202496 517 0 0 0 1 0 0 0 25 0 1 0 11206926 4210688 445 1283457024 134512640 134752139 4290686384 18446744073709551615 134681846 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/25979/statm: 1028 445 286 59 0 192 0

[startup+0.143374 s]
/proc/loadavg: 1.62 1.45 1.31 5/36 25979
/proc/meminfo: memFree=283444/1048576 swapFree=0/0
[pid=25978] ppid=25977 vsize=2572 CPUtime=0
/proc/25978/stat : 25978 (packup2mp4pa-0.) S 25977 25978 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11206926 2633728 275 1283457024 134512640 135304128 4288123760 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/25978/statm: 643 275 233 194 0 30 0
[pid=25979] ppid=25978 vsize=8972 CPUtime=0.14
/proc/25979/stat : 25979 (packup) R 25978 25978 4778 34817 4778 4202496 1724 0 0 0 12 2 0 0 25 0 1 0 11206926 9187328 1652 1283457024 134512640 134752139 4290686384 18446744073709551615 134682962 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/25979/statm: 2243 1652 286 59 0 1407 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 11544

[startup+0.213383 s]
/proc/loadavg: 1.62 1.45 1.31 5/36 25979
/proc/meminfo: memFree=283444/1048576 swapFree=0/0
[pid=25978] ppid=25977 vsize=2572 CPUtime=0
/proc/25978/stat : 25978 (packup2mp4pa-0.) S 25977 25978 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11206926 2633728 275 1283457024 134512640 135304128 4288123760 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/25978/statm: 643 275 233 194 0 30 0
[pid=25979] ppid=25978 vsize=11348 CPUtime=0.21
/proc/25979/stat : 25979 (packup) R 25978 25978 4778 34817 4778 4202496 2317 0 0 0 19 2 0 0 25 0 1 0 11206926 11620352 2245 1283457024 134512640 134752139 4290686384 18446744073709551615 134706520 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/25979/statm: 2837 2245 286 59 0 2001 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 13920

[startup+0.303395 s]
/proc/loadavg: 1.62 1.45 1.31 5/36 25979
/proc/meminfo: memFree=283444/1048576 swapFree=0/0
[pid=25978] ppid=25977 vsize=2572 CPUtime=0
/proc/25978/stat : 25978 (packup2mp4pa-0.) S 25977 25978 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11206926 2633728 275 1283457024 134512640 135304128 4288123760 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/25978/statm: 643 275 233 194 0 30 0
[pid=25979] ppid=25978 vsize=14120 CPUtime=0.3
/proc/25979/stat : 25979 (packup) R 25978 25978 4778 34817 4778 4202496 3009 0 0 0 28 2 0 0 25 0 1 0 11206926 14458880 2937 1283457024 134512640 134752139 4290686384 18446744073709551615 134681674 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/25979/statm: 3530 2937 286 59 0 2694 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16692

[startup+0.703452 s]
/proc/loadavg: 1.62 1.45 1.31 5/36 25979
/proc/meminfo: memFree=283444/1048576 swapFree=0/0
[pid=25978] ppid=25977 vsize=2572 CPUtime=0
/proc/25978/stat : 25978 (packup2mp4pa-0.) S 25977 25978 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11206926 2633728 275 1283457024 134512640 135304128 4288123760 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/25978/statm: 643 275 233 194 0 30 0
[pid=25979] ppid=25978 vsize=25008 CPUtime=0.7
/proc/25979/stat : 25979 (packup) R 25978 25978 4778 34817 4778 4202496 5745 0 0 0 68 2 0 0 25 0 1 0 11206926 25608192 5673 1283457024 134512640 134752139 4290686384 18446744073709551615 134681812 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/25979/statm: 6252 5673 286 59 0 5416 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 27580

[startup+1.50354 s]
/proc/loadavg: 1.62 1.45 1.31 2/37 25980
/proc/meminfo: memFree=249136/1048576 swapFree=0/0
[pid=25978] ppid=25977 vsize=2572 CPUtime=0
/proc/25978/stat : 25978 (packup2mp4pa-0.) S 25977 25978 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11206926 2633728 275 1283457024 134512640 135304128 4288123760 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/25978/statm: 643 275 233 194 0 30 0
[pid=25979] ppid=25978 vsize=45708 CPUtime=1.48
/proc/25979/stat : 25979 (packup) S 25978 25978 4778 34817 4778 4202496 11060 0 0 0 128 20 0 0 25 0 1 0 11206926 46804992 10711 1283457024 134512640 134752139 4290686384 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/25979/statm: 11427 10711 324 59 0 10591 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 48280

[startup+3.10375 s]
/proc/loadavg: 1.62 1.45 1.31 2/39 25982
/proc/meminfo: memFree=224676/1048576 swapFree=0/0
[pid=25978] ppid=25977 vsize=2572 CPUtime=0
/proc/25978/stat : 25978 (packup2mp4pa-0.) S 25977 25978 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11206926 2633728 275 1283457024 134512640 135304128 4288123760 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/25978/statm: 643 275 233 194 0 30 0
[pid=25979] ppid=25978 vsize=45708 CPUtime=1.48
/proc/25979/stat : 25979 (packup) S 25978 25978 4778 34817 4778 4202496 11060 0 0 0 128 20 0 0 25 0 1 0 11206926 46804992 10711 1283457024 134512640 134752139 4290686384 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/25979/statm: 11427 10711 324 59 0 10591 0
[pid=25981] ppid=25979 vsize=1672 CPUtime=0.01
/proc/25981/stat : 25981 (sh) S 25979 25978 4778 34817 4778 4202496 147 0 0 0 0 1 0 0 25 0 1 0 11207073 1712128 124 1283457024 134512640 134593992 4288615568 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25981/statm: 418 124 108 20 0 45 0
[pid=25982] ppid=25981 vsize=61720 CPUtime=1.61
/proc/25982/stat : 25982 (minisatp_32) R 25981 25978 4778 34817 4778 4202496 18239 0 0 0 137 24 0 0 25 0 1 0 11207074 63201280 13521 1283457024 134512640 135413687 4288343152 18446744073709551615 134686170 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/25982/statm: 15430 13521 107 220 0 15208 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 111672

[startup+6.30417 s]
/proc/loadavg: 1.57 1.44 1.31 2/39 25984
/proc/meminfo: memFree=217988/1048576 swapFree=0/0
[pid=25978] ppid=25977 vsize=2572 CPUtime=0
/proc/25978/stat : 25978 (packup2mp4pa-0.) S 25977 25978 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11206926 2633728 275 1283457024 134512640 135304128 4288123760 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/25978/statm: 643 275 233 194 0 30 0
[pid=25979] ppid=25978 vsize=45712 CPUtime=4.37
/proc/25979/stat : 25979 (packup) S 25978 25978 4778 34817 4778 4202496 11133 25316 0 0 137 36 236 28 18 0 1 0 11206926 46809088 10720 1283457024 134512640 134752139 4290686384 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/25979/statm: 11428 10720 332 59 0 10592 0
[pid=25983] ppid=25979 vsize=1676 CPUtime=0
/proc/25983/stat : 25983 (sh) S 25979 25978 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 19 0 1 0 11207365 1716224 124 1283457024 134512640 134593992 4292794512 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25983/statm: 419 124 108 20 0 46 0
[pid=25984] ppid=25983 vsize=85372 CPUtime=1.9
/proc/25984/stat : 25984 (minisatp_32) R 25983 25978 4778 34817 4778 4202496 23455 0 0 0 172 18 0 0 25 0 1 0 11207366 87420928 18434 1283457024 134512640 135413687 4287845360 18446744073709551615 134686573 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/25984/statm: 21343 18434 108 220 0 21121 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 135332

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

[startup+6.40418 s]
/proc/loadavg: 1.57 1.44 1.31 2/39 25984
/proc/meminfo: memFree=217988/1048576 swapFree=0/0
[pid=25978] ppid=25977 vsize=2572 CPUtime=0
/proc/25978/stat : 25978 (packup2mp4pa-0.) S 25977 25978 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11206926 2633728 275 1283457024 134512640 135304128 4288123760 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/25978/statm: 643 275 233 194 0 30 0
[pid=25979] ppid=25978 vsize=45712 CPUtime=4.37
/proc/25979/stat : 25979 (packup) S 25978 25978 4778 34817 4778 4202496 11133 25316 0 0 137 36 236 28 18 0 1 0 11206926 46809088 10720 1283457024 134512640 134752139 4290686384 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/25979/statm: 11428 10720 332 59 0 10592 0
[pid=25983] ppid=25979 vsize=1676 CPUtime=0
/proc/25983/stat : 25983 (sh) S 25979 25978 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 19 0 1 0 11207365 1716224 124 1283457024 134512640 134593992 4292794512 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25983/statm: 419 124 108 20 0 46 0
[pid=25984] ppid=25983 vsize=88928 CPUtime=2
/proc/25984/stat : 25984 (minisatp_32) R 25983 25978 4778 34817 4778 4202496 24493 0 0 0 182 18 0 0 25 0 1 0 11207366 91062272 19434 1283457024 134512640 135413687 4287845360 18446744073709551615 134682747 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/25984/statm: 22232 19434 108 220 0 22010 0
Current children cumulated CPU time (s) 6.37
Current children cumulated vsize (KiB) 138888

[startup+7.2043 s]
/proc/loadavg: 1.57 1.44 1.31 2/39 25984
/proc/meminfo: memFree=165536/1048576 swapFree=0/0
[pid=25978] ppid=25977 vsize=2572 CPUtime=0
/proc/25978/stat : 25978 (packup2mp4pa-0.) S 25977 25978 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11206926 2633728 275 1283457024 134512640 135304128 4288123760 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/25978/statm: 643 275 233 194 0 30 0
[pid=25979] ppid=25978 vsize=45712 CPUtime=4.37
/proc/25979/stat : 25979 (packup) S 25978 25978 4778 34817 4778 4202496 11133 25316 0 0 137 36 236 28 18 0 1 0 11206926 46809088 10720 1283457024 134512640 134752139 4290686384 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/25979/statm: 11428 10720 332 59 0 10592 0
[pid=25983] ppid=25979 vsize=1676 CPUtime=0
/proc/25983/stat : 25983 (sh) S 25979 25978 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 19 0 1 0 11207365 1716224 124 1283457024 134512640 134593992 4292794512 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/25983/statm: 419 124 108 20 0 46 0
[pid=25984] ppid=25983 vsize=99728 CPUtime=2.8
/proc/25984/stat : 25984 (minisatp_32) R 25983 25978 4778 34817 4778 4202496 28554 0 0 0 261 19 0 0 25 0 1 0 11207366 102121472 21121 1283457024 134512640 135413687 4287845360 18446744073709551615 134657019 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/25984/statm: 24932 21121 108 220 0 24710 0
Current children cumulated CPU time (s) 7.17
Current children cumulated vsize (KiB) 149688

[startup+7.40432 s]
/proc/loadavg: 1.57 1.44 1.31 2/39 25984
/proc/meminfo: memFree=165536/1048576 swapFree=0/0
[pid=25978] ppid=25977 vsize=2572 CPUtime=0
/proc/25978/stat : 25978 (packup2mp4pa-0.) S 25977 25978 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11206926 2633728 275 1283457024 134512640 135304128 4288123760 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/25978/statm: 643 275 233 194 0 30 0
[pid=25979] ppid=25978 vsize=44940 CPUtime=7.39
/proc/25979/stat : 25979 (packup) R 25978 25978 4778 34817 4778 4202496 19198 54183 0 0 141 40 510 48 18 0 1 0 11206926 46018560 10540 1283457024 134512640 134752139 4290686384 18446744073709551615 4159336644 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/25979/statm: 11235 10540 345 59 0 10399 0
Current children cumulated CPU time (s) 7.39
Current children cumulated vsize (KiB) 47512

Child status: 0
Real time (s): 7.47054
CPU time (s): 7.47247
CPU user time (s): 6.56841
CPU system time (s): 0.904056
CPU usage (%): 100.026
Max. virtual memory (cumulated for all children) (KiB): 149688

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.56841
system time used= 0.904056
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 75558
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= 11
involuntary context switches= 130

runsolver used 0 second user time and 0 second system time

The end