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/rand115.cudf.s-e-l.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/incremental/s-e-l/rand115.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/rand115.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.21 1.03 0.70 5/35 5621
/proc/meminfo: memFree=355664/1048576 swapFree=0/0
[pid=5620] ppid=5619 vsize=2568 CPUtime=0
/proc/5620/stat : 5620 (packup2mp4pa-0.) R 5619 5620 4778 34817 4778 4202496 360 0 0 0 0 0 0 0 25 0 1 0 10049955 2629632 274 1283457024 134512640 135304128 4294142304 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/5620/statm: 642 274 233 194 0 29 0
[pid=5621] ppid=5620 vsize=2568 CPUtime=0
/proc/5621/stat : 5621 (packup2mp4pa-0.) R 5620 5620 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10049955 2629632 41 1283457024 134512640 135304128 4294142304 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/5621/statm: 642 41 0 194 0 29 0

[startup+0.174146 s]
/proc/loadavg: 1.21 1.03 0.70 5/35 5621
/proc/meminfo: memFree=355664/1048576 swapFree=0/0
[pid=5620] ppid=5619 vsize=2568 CPUtime=0
/proc/5620/stat : 5620 (packup2mp4pa-0.) S 5619 5620 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10049955 2629632 274 1283457024 134512640 135304128 4294142304 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/5620/statm: 642 274 233 194 0 29 0
[pid=5621] ppid=5620 vsize=10180 CPUtime=0.18
/proc/5621/stat : 5621 (packup) R 5620 5620 4778 34817 4778 4202496 2024 0 0 0 16 2 0 0 25 0 1 0 10049955 10424320 1953 1283457024 134512640 134752139 4287890240 18446744073709551615 134681791 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/5621/statm: 2545 1953 286 59 0 1709 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 12748

[startup+0.204158 s]
/proc/loadavg: 1.21 1.03 0.70 5/35 5621
/proc/meminfo: memFree=355664/1048576 swapFree=0/0
[pid=5620] ppid=5619 vsize=2568 CPUtime=0
/proc/5620/stat : 5620 (packup2mp4pa-0.) S 5619 5620 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10049955 2629632 274 1283457024 134512640 135304128 4294142304 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/5620/statm: 642 274 233 194 0 29 0
[pid=5621] ppid=5620 vsize=11104 CPUtime=0.2
/proc/5621/stat : 5621 (packup) R 5620 5620 4778 34817 4778 4202496 2264 0 0 0 18 2 0 0 25 0 1 0 10049955 11370496 2193 1283457024 134512640 134752139 4287890240 18446744073709551615 4157890106 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/5621/statm: 2776 2193 286 59 0 1940 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13672

[startup+0.304175 s]
/proc/loadavg: 1.21 1.03 0.70 5/35 5621
/proc/meminfo: memFree=355664/1048576 swapFree=0/0
[pid=5620] ppid=5619 vsize=2568 CPUtime=0
/proc/5620/stat : 5620 (packup2mp4pa-0.) S 5619 5620 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10049955 2629632 274 1283457024 134512640 135304128 4294142304 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/5620/statm: 642 274 233 194 0 29 0
[pid=5621] ppid=5620 vsize=14272 CPUtime=0.3
/proc/5621/stat : 5621 (packup) R 5620 5620 4778 34817 4778 4202496 3051 0 0 0 28 2 0 0 25 0 1 0 10049955 14614528 2980 1283457024 134512640 134752139 4287890240 18446744073709551615 4159810432 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/5621/statm: 3568 2980 286 59 0 2732 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16840

[startup+0.704248 s]
/proc/loadavg: 1.21 1.03 0.70 5/35 5621
/proc/meminfo: memFree=355664/1048576 swapFree=0/0
[pid=5620] ppid=5619 vsize=2568 CPUtime=0
/proc/5620/stat : 5620 (packup2mp4pa-0.) S 5619 5620 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10049955 2629632 274 1283457024 134512640 135304128 4294142304 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/5620/statm: 642 274 233 194 0 29 0
[pid=5621] ppid=5620 vsize=25028 CPUtime=0.7
/proc/5621/stat : 5621 (packup) R 5620 5620 4778 34817 4778 4202496 5762 0 0 0 67 3 0 0 25 0 1 0 10049955 25628672 5691 1283457024 134512640 134752139 4287890240 18446744073709551615 134706154 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/5621/statm: 6257 5691 286 59 0 5421 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 27596

[startup+1.50451 s]
/proc/loadavg: 1.21 1.03 0.70 2/36 5622
/proc/meminfo: memFree=319568/1048576 swapFree=0/0
[pid=5620] ppid=5619 vsize=2568 CPUtime=0
/proc/5620/stat : 5620 (packup2mp4pa-0.) S 5619 5620 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10049955 2629632 274 1283457024 134512640 135304128 4294142304 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/5620/statm: 642 274 233 194 0 29 0
[pid=5621] ppid=5620 vsize=39376 CPUtime=1.21
/proc/5621/stat : 5621 (packup) S 5620 5620 4778 34817 4778 4202496 9466 0 0 0 103 18 0 0 25 0 1 0 10049955 40321024 9150 1283457024 134512640 134752139 4287890240 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/5621/statm: 9844 9150 324 59 0 9008 0
Current children cumulated CPU time (s) 1.21
Current children cumulated vsize (KiB) 41944

[startup+3.10529 s]
/proc/loadavg: 1.19 1.03 0.70 2/38 5624
/proc/meminfo: memFree=299820/1048576 swapFree=0/0
[pid=5620] ppid=5619 vsize=2568 CPUtime=0
/proc/5620/stat : 5620 (packup2mp4pa-0.) S 5619 5620 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10049955 2629632 274 1283457024 134512640 135304128 4294142304 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/5620/statm: 642 274 233 194 0 29 0
[pid=5621] ppid=5620 vsize=39380 CPUtime=2.64
/proc/5621/stat : 5621 (packup) S 5620 5620 4778 34817 4778 4202496 9519 9017 0 0 114 28 110 12 18 0 1 0 10049955 40325120 9159 1283457024 134512640 134752139 4287890240 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/5621/statm: 9845 9159 332 59 0 9009 0
Current children cumulated CPU time (s) 2.64
Current children cumulated vsize (KiB) 41948

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

[startup+3.20532 s]
/proc/loadavg: 1.19 1.03 0.70 2/38 5624
/proc/meminfo: memFree=299820/1048576 swapFree=0/0
[pid=5620] ppid=5619 vsize=2568 CPUtime=0
/proc/5620/stat : 5620 (packup2mp4pa-0.) S 5619 5620 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10049955 2629632 274 1283457024 134512640 135304128 4294142304 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/5620/statm: 642 274 233 194 0 29 0
[pid=5621] ppid=5620 vsize=39380 CPUtime=2.64
/proc/5621/stat : 5621 (packup) S 5620 5620 4778 34817 4778 4202496 9519 9017 0 0 114 28 110 12 18 0 1 0 10049955 40325120 9159 1283457024 134512640 134752139 4287890240 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/5621/statm: 9845 9159 332 59 0 9009 0
Current children cumulated CPU time (s) 2.64
Current children cumulated vsize (KiB) 41948

[startup+4.80603 s]
/proc/loadavg: 1.19 1.03 0.70 2/38 5626
/proc/meminfo: memFree=262124/1048576 swapFree=0/0
[pid=5620] ppid=5619 vsize=2568 CPUtime=0
/proc/5620/stat : 5620 (packup2mp4pa-0.) S 5619 5620 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10049955 2629632 274 1283457024 134512640 135304128 4294142304 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/5620/statm: 642 274 233 194 0 29 0
[pid=5621] ppid=5620 vsize=39380 CPUtime=2.64
/proc/5621/stat : 5621 (packup) S 5620 5620 4778 34817 4778 4202496 9519 9017 0 0 114 28 110 12 18 0 1 0 10049955 40325120 9159 1283457024 134512640 134752139 4287890240 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/5621/statm: 9845 9159 332 59 0 9009 0
[pid=5625] ppid=5621 vsize=1672 CPUtime=0
/proc/5625/stat : 5625 (sh) S 5621 5620 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 10050221 1712128 124 1283457024 134512640 134593992 4293130464 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/5625/statm: 418 124 108 20 0 45 0
[pid=5626] ppid=5625 vsize=67480 CPUtime=2.13
/proc/5626/stat : 5626 (minisatp_32) R 5625 5620 4778 34817 4778 4202496 21903 0 0 0 195 18 0 0 25 0 1 0 10050222 69099520 15090 1283457024 134512640 135413687 4294619760 18446744073709551615 134699129 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/5626/statm: 16870 15090 107 220 0 16648 0
Current children cumulated CPU time (s) 4.77
Current children cumulated vsize (KiB) 111100

[startup+5.20624 s]
/proc/loadavg: 1.19 1.03 0.70 2/38 5626
/proc/meminfo: memFree=262124/1048576 swapFree=0/0
[pid=5620] ppid=5619 vsize=2568 CPUtime=0
/proc/5620/stat : 5620 (packup2mp4pa-0.) S 5619 5620 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10049955 2629632 274 1283457024 134512640 135304128 4294142304 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/5620/statm: 642 274 233 194 0 29 0
[pid=5621] ppid=5620 vsize=39380 CPUtime=2.64
/proc/5621/stat : 5621 (packup) S 5620 5620 4778 34817 4778 4202496 9519 9017 0 0 114 28 110 12 18 0 1 0 10049955 40325120 9159 1283457024 134512640 134752139 4287890240 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/5621/statm: 9845 9159 332 59 0 9009 0
[pid=5625] ppid=5621 vsize=1672 CPUtime=0
/proc/5625/stat : 5625 (sh) S 5621 5620 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 10050221 1712128 124 1283457024 134512640 134593992 4293130464 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/5625/statm: 418 124 108 20 0 45 0
[pid=5626] ppid=5625 vsize=71052 CPUtime=2.53
/proc/5626/stat : 5626 (minisatp_32) R 5625 5620 4778 34817 4778 4202496 22129 0 0 0 235 18 0 0 25 0 1 0 10050222 72757248 15295 1283457024 134512640 135413687 4294619760 18446744073709551615 134704558 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/5626/statm: 17763 15295 107 220 0 17541 0
Current children cumulated CPU time (s) 5.17
Current children cumulated vsize (KiB) 114672

[startup+5.60644 s]
/proc/loadavg: 1.19 1.03 0.70 2/38 5626
/proc/meminfo: memFree=257660/1048576 swapFree=0/0
[pid=5620] ppid=5619 vsize=2568 CPUtime=0
/proc/5620/stat : 5620 (packup2mp4pa-0.) S 5619 5620 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10049955 2629632 274 1283457024 134512640 135304128 4294142304 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/5620/statm: 642 274 233 194 0 29 0
[pid=5621] ppid=5620 vsize=37052 CPUtime=5.59
/proc/5621/stat : 5621 (packup) R 5620 5620 4778 34817 4778 4202496 17692 32280 0 0 117 31 378 33 18 0 1 0 10049955 37941248 8733 1283457024 134512640 134752139 4287890240 18446744073709551615 134555026 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/5621/statm: 9263 8733 345 59 0 8427 0
Current children cumulated CPU time (s) 5.59
Current children cumulated vsize (KiB) 39620

Child status: 0
Real time (s): 5.61957
CPU time (s): 5.62035
CPU user time (s): 4.96031
CPU system time (s): 0.660041
CPU usage (%): 100.014
Max. virtual memory (cumulated for all children) (KiB): 122332

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

runsolver used 0 second user time and 0 second system time

The end