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/rand399.cudf.s-e-l.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/incremental/s-e-l/rand399.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/rand399.cudf.s-e-l.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.12 1.04 1.01 4/36 11407
/proc/meminfo: memFree=357216/1048576 swapFree=0/0
[pid=11406] ppid=11405 vsize=2572 CPUtime=0
/proc/11406/stat : 11406 (packup2mp4pa-0.) S 11405 11406 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 10564045 2633728 275 1283457024 134512640 135304128 4291786528 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11406/statm: 643 275 233 194 0 30 0
[pid=11407] ppid=11406 vsize=3716 CPUtime=0.01
/proc/11407/stat : 11407 (packup) R 11406 11406 4778 34817 4778 4202496 407 0 0 0 1 0 0 0 25 0 1 0 10564046 3805184 336 1283457024 134512640 134752139 4293921024 18446744073709551615 4158812016 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/11407/statm: 929 336 286 59 0 93 0

[startup+0.183774 s]
/proc/loadavg: 1.12 1.04 1.01 4/36 11407
/proc/meminfo: memFree=357216/1048576 swapFree=0/0
[pid=11406] ppid=11405 vsize=2572 CPUtime=0
/proc/11406/stat : 11406 (packup2mp4pa-0.) S 11405 11406 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 10564045 2633728 275 1283457024 134512640 135304128 4291786528 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11406/statm: 643 275 233 194 0 30 0
[pid=11407] ppid=11406 vsize=10448 CPUtime=0.19
/proc/11407/stat : 11407 (packup) R 11406 11406 4778 34817 4778 4202496 2089 0 0 0 17 2 0 0 25 0 1 0 10564046 10698752 2018 1283457024 134512640 134752139 4293921024 18446744073709551615 134681788 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/11407/statm: 2612 2018 286 59 0 1776 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 13020

[startup+0.21378 s]
/proc/loadavg: 1.12 1.04 1.01 4/36 11407
/proc/meminfo: memFree=357216/1048576 swapFree=0/0
[pid=11406] ppid=11405 vsize=2572 CPUtime=0
/proc/11406/stat : 11406 (packup2mp4pa-0.) S 11405 11406 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 10564045 2633728 275 1283457024 134512640 135304128 4291786528 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11406/statm: 643 275 233 194 0 30 0
[pid=11407] ppid=11406 vsize=11372 CPUtime=0.22
/proc/11407/stat : 11407 (packup) R 11406 11406 4778 34817 4778 4202496 2331 0 0 0 20 2 0 0 25 0 1 0 10564046 11644928 2260 1283457024 134512640 134752139 4293921024 18446744073709551615 134681674 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/11407/statm: 2843 2260 286 59 0 2007 0
Current children cumulated CPU time (s) 0.22
Current children cumulated vsize (KiB) 13944

[startup+0.303801 s]
/proc/loadavg: 1.12 1.04 1.01 4/36 11407
/proc/meminfo: memFree=357216/1048576 swapFree=0/0
[pid=11406] ppid=11405 vsize=2572 CPUtime=0
/proc/11406/stat : 11406 (packup2mp4pa-0.) S 11405 11406 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 10564045 2633728 275 1283457024 134512640 135304128 4291786528 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11406/statm: 643 275 233 194 0 30 0
[pid=11407] ppid=11406 vsize=14144 CPUtime=0.31
/proc/11407/stat : 11407 (packup) R 11406 11406 4778 34817 4778 4202496 3020 0 0 0 29 2 0 0 25 0 1 0 10564046 14483456 2949 1283457024 134512640 134752139 4293921024 18446744073709551615 4157021082 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/11407/statm: 3536 2949 286 59 0 2700 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 16716

[startup+0.703884 s]
/proc/loadavg: 1.12 1.04 1.01 4/36 11407
/proc/meminfo: memFree=357216/1048576 swapFree=0/0
[pid=11406] ppid=11405 vsize=2572 CPUtime=0
/proc/11406/stat : 11406 (packup2mp4pa-0.) S 11405 11406 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 10564045 2633728 275 1283457024 134512640 135304128 4291786528 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11406/statm: 643 275 233 194 0 30 0
[pid=11407] ppid=11406 vsize=24636 CPUtime=0.7
/proc/11407/stat : 11407 (packup) R 11406 11406 4778 34817 4778 4202496 5637 0 0 0 68 2 0 0 25 0 1 0 10564046 25227264 5566 1283457024 134512640 134752139 4293921024 18446744073709551615 4157048195 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/11407/statm: 6159 5566 286 59 0 5323 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 27208

[startup+1.50406 s]
/proc/loadavg: 1.12 1.04 1.01 2/37 11408
/proc/meminfo: memFree=321492/1048576 swapFree=0/0
[pid=11406] ppid=11405 vsize=2572 CPUtime=0
/proc/11406/stat : 11406 (packup2mp4pa-0.) S 11405 11406 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 10564045 2633728 275 1283457024 134512640 135304128 4291786528 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11406/statm: 643 275 233 194 0 30 0
[pid=11407] ppid=11406 vsize=39312 CPUtime=1.23
/proc/11407/stat : 11407 (packup) S 11406 11406 4778 34817 4778 4202496 9443 0 0 0 99 24 0 0 25 0 1 0 10564046 40255488 9128 1283457024 134512640 134752139 4293921024 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/11407/statm: 9828 9128 324 59 0 8992 0
Current children cumulated CPU time (s) 1.23
Current children cumulated vsize (KiB) 41884

[startup+3.10438 s]
/proc/loadavg: 1.19 1.06 1.01 2/39 11410
/proc/meminfo: memFree=300876/1048576 swapFree=0/0
[pid=11406] ppid=11405 vsize=2572 CPUtime=0
/proc/11406/stat : 11406 (packup2mp4pa-0.) S 11405 11406 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 10564045 2633728 275 1283457024 134512640 135304128 4291786528 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11406/statm: 643 275 233 194 0 30 0
[pid=11407] ppid=11406 vsize=39316 CPUtime=2.73
/proc/11407/stat : 11407 (packup) S 11406 11406 4778 34817 4778 4202496 9496 9177 0 0 106 39 114 14 18 0 1 0 10564046 40259584 9137 1283457024 134512640 134752139 4293921024 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/11407/statm: 9829 9137 332 59 0 8993 0
Current children cumulated CPU time (s) 2.73
Current children cumulated vsize (KiB) 41888

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

[startup+3.2044 s]
/proc/loadavg: 1.19 1.06 1.01 2/39 11410
/proc/meminfo: memFree=300876/1048576 swapFree=0/0
[pid=11406] ppid=11405 vsize=2572 CPUtime=0
/proc/11406/stat : 11406 (packup2mp4pa-0.) S 11405 11406 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 10564045 2633728 275 1283457024 134512640 135304128 4291786528 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11406/statm: 643 275 233 194 0 30 0
[pid=11407] ppid=11406 vsize=39316 CPUtime=2.73
/proc/11407/stat : 11407 (packup) S 11406 11406 4778 34817 4778 4202496 9496 9177 0 0 106 39 114 14 18 0 1 0 10564046 40259584 9137 1283457024 134512640 134752139 4293921024 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/11407/statm: 9829 9137 332 59 0 8993 0
Current children cumulated CPU time (s) 2.73
Current children cumulated vsize (KiB) 41888

[startup+4.80475 s]
/proc/loadavg: 1.19 1.06 1.01 2/39 11412
/proc/meminfo: memFree=268512/1048576 swapFree=0/0
[pid=11406] ppid=11405 vsize=2572 CPUtime=0
/proc/11406/stat : 11406 (packup2mp4pa-0.) S 11405 11406 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 10564045 2633728 275 1283457024 134512640 135304128 4291786528 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11406/statm: 643 275 233 194 0 30 0
[pid=11407] ppid=11406 vsize=39316 CPUtime=2.73
/proc/11407/stat : 11407 (packup) S 11406 11406 4778 34817 4778 4202496 9496 9177 0 0 106 39 114 14 18 0 1 0 10564046 40259584 9137 1283457024 134512640 134752139 4293921024 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/11407/statm: 9829 9137 332 59 0 8993 0
[pid=11411] ppid=11407 vsize=1668 CPUtime=0
/proc/11411/stat : 11411 (sh) S 11407 11406 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 10564319 1708032 123 1283457024 134512640 134593992 4290625152 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/11411/statm: 417 123 108 20 0 44 0
[pid=11412] ppid=11411 vsize=80448 CPUtime=2.06
/proc/11412/stat : 11412 (minisatp_32) R 11411 11406 4778 34817 4778 4202496 21647 0 0 0 180 26 0 0 25 0 1 0 10564319 82378752 16403 1283457024 134512640 135413687 4294746768 18446744073709551615 134688068 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/11412/statm: 20112 16403 107 220 0 19890 0
Current children cumulated CPU time (s) 4.79
Current children cumulated vsize (KiB) 124004

[startup+5.20486 s]
/proc/loadavg: 1.19 1.06 1.01 2/39 11412
/proc/meminfo: memFree=268512/1048576 swapFree=0/0
[pid=11406] ppid=11405 vsize=2572 CPUtime=0
/proc/11406/stat : 11406 (packup2mp4pa-0.) S 11405 11406 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 10564045 2633728 275 1283457024 134512640 135304128 4291786528 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11406/statm: 643 275 233 194 0 30 0
[pid=11407] ppid=11406 vsize=39316 CPUtime=2.73
/proc/11407/stat : 11407 (packup) S 11406 11406 4778 34817 4778 4202496 9496 9177 0 0 106 39 114 14 18 0 1 0 10564046 40259584 9137 1283457024 134512640 134752139 4293921024 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/11407/statm: 9829 9137 332 59 0 8993 0
[pid=11411] ppid=11407 vsize=1668 CPUtime=0
/proc/11411/stat : 11411 (sh) S 11407 11406 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 10564319 1708032 123 1283457024 134512640 134593992 4290625152 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/11411/statm: 417 123 108 20 0 44 0
[pid=11412] ppid=11411 vsize=72192 CPUtime=2.46
/proc/11412/stat : 11412 (minisatp_32) R 11411 11406 4778 34817 4778 4202496 22937 0 0 0 219 27 0 0 25 0 1 0 10564319 73924608 15748 1283457024 134512640 135413687 4294746768 18446744073709551615 134577088 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/11412/statm: 18048 15748 107 220 0 17826 0
Current children cumulated CPU time (s) 5.19
Current children cumulated vsize (KiB) 115748

[startup+5.60494 s]
/proc/loadavg: 1.19 1.06 1.01 2/39 11412
/proc/meminfo: memFree=256360/1048576 swapFree=0/0
[pid=11406] ppid=11405 vsize=2572 CPUtime=0
/proc/11406/stat : 11406 (packup2mp4pa-0.) S 11405 11406 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 10564045 2633728 275 1283457024 134512640 135304128 4291786528 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11406/statm: 643 275 233 194 0 30 0
[pid=11407] ppid=11406 vsize=39320 CPUtime=5.6
/proc/11407/stat : 11407 (packup) R 11406 11406 4778 34817 4778 4202496 9565 33412 0 0 107 39 370 44 18 0 1 0 10564046 40263680 9151 1283457024 134512640 134752139 4293921024 18446744073709551615 4158589039 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/11407/statm: 9830 9151 345 59 0 8994 0
Current children cumulated CPU time (s) 5.6
Current children cumulated vsize (KiB) 41892

Child status: 0
Real time (s): 5.67181
CPU time (s): 5.66835
CPU user time (s): 4.8123
CPU system time (s): 0.856053
CPU usage (%): 99.939
Max. virtual memory (cumulated for all children) (KiB): 124004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.8123
system time used= 0.856053
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 51625
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= 110

runsolver used 0 second user time and 0 second system time

The end