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/rand21.cudf.dudf-random.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-random//rand21.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/rand21.cudf.dudf-random.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.19 0.78 5/34 6325
/proc/meminfo: memFree=342236/1048576 swapFree=0/0
[pid=6324] ppid=6323 vsize=2572 CPUtime=0
/proc/6324/stat : 6324 (packup2mp4pa-0.) S 6323 6324 4778 34817 4778 4202496 381 0 0 0 0 0 0 0 25 0 1 0 10058069 2633728 275 1283457024 134512640 135304128 4288889952 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/6324/statm: 643 275 233 194 0 30 0
[pid=6325] ppid=6324 vsize=3976 CPUtime=0.01
/proc/6325/stat : 6325 (packup) R 6324 6324 4778 34817 4778 4202496 496 0 0 0 0 1 0 0 25 0 1 0 10058069 4071424 424 1283457024 134512640 134752139 4289379488 18446744073709551615 4157289187 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/6325/statm: 994 424 286 59 0 158 0

[startup+0.192232 s]
/proc/loadavg: 1.60 1.19 0.78 5/34 6325
/proc/meminfo: memFree=342236/1048576 swapFree=0/0
[pid=6324] ppid=6323 vsize=2572 CPUtime=0
/proc/6324/stat : 6324 (packup2mp4pa-0.) S 6323 6324 4778 34817 4778 4202496 381 0 0 0 0 0 0 0 25 0 1 0 10058069 2633728 275 1283457024 134512640 135304128 4288889952 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/6324/statm: 643 275 233 194 0 30 0
[pid=6325] ppid=6324 vsize=9824 CPUtime=0.19
/proc/6325/stat : 6325 (packup) R 6324 6324 4778 34817 4778 4202496 1938 0 0 0 18 1 0 0 25 0 1 0 10058069 10059776 1866 1283457024 134512640 134752139 4289379488 18446744073709551615 134681826 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/6325/statm: 2456 1866 286 59 0 1620 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 12396

[startup+0.20223 s]
/proc/loadavg: 1.60 1.19 0.78 5/34 6325
/proc/meminfo: memFree=342236/1048576 swapFree=0/0
[pid=6324] ppid=6323 vsize=2572 CPUtime=0
/proc/6324/stat : 6324 (packup2mp4pa-0.) S 6323 6324 4778 34817 4778 4202496 381 0 0 0 0 0 0 0 25 0 1 0 10058069 2633728 275 1283457024 134512640 135304128 4288889952 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/6324/statm: 643 275 233 194 0 30 0
[pid=6325] ppid=6324 vsize=10088 CPUtime=0.19
/proc/6325/stat : 6325 (packup) R 6324 6324 4778 34817 4778 4202496 2012 0 0 0 18 1 0 0 25 0 1 0 10058069 10330112 1940 1283457024 134512640 134752139 4289379488 18446744073709551615 134681659 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/6325/statm: 2522 1940 286 59 0 1686 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 12660

[startup+0.31225 s]
/proc/loadavg: 1.60 1.19 0.78 5/34 6325
/proc/meminfo: memFree=342236/1048576 swapFree=0/0
[pid=6324] ppid=6323 vsize=2572 CPUtime=0
/proc/6324/stat : 6324 (packup2mp4pa-0.) S 6323 6324 4778 34817 4778 4202496 381 0 0 0 0 0 0 0 25 0 1 0 10058069 2633728 275 1283457024 134512640 135304128 4288889952 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/6324/statm: 643 275 233 194 0 30 0
[pid=6325] ppid=6324 vsize=13108 CPUtime=0.31
/proc/6325/stat : 6325 (packup) R 6324 6324 4778 34817 4778 4202496 2776 0 0 0 27 4 0 0 25 0 1 0 10058069 13422592 2704 1283457024 134512640 134752139 4289379488 18446744073709551615 134681767 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/6325/statm: 3277 2704 286 59 0 2441 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15680

[startup+0.712318 s]
/proc/loadavg: 1.60 1.19 0.78 5/34 6325
/proc/meminfo: memFree=342236/1048576 swapFree=0/0
[pid=6324] ppid=6323 vsize=2572 CPUtime=0
/proc/6324/stat : 6324 (packup2mp4pa-0.) S 6323 6324 4778 34817 4778 4202496 381 0 0 0 0 0 0 0 25 0 1 0 10058069 2633728 275 1283457024 134512640 135304128 4288889952 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/6324/statm: 643 275 233 194 0 30 0
[pid=6325] ppid=6324 vsize=22940 CPUtime=0.71
/proc/6325/stat : 6325 (packup) R 6324 6324 4778 34817 4778 4202496 5217 0 0 0 63 8 0 0 25 0 1 0 10058069 23490560 5145 1283457024 134512640 134752139 4289379488 18446744073709551615 134707183 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/6325/statm: 5735 5145 286 59 0 4899 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 25512

[startup+1.51256 s]
/proc/loadavg: 1.55 1.18 0.78 2/35 6326
/proc/meminfo: memFree=314200/1048576 swapFree=0/0
[pid=6324] ppid=6323 vsize=2572 CPUtime=0
/proc/6324/stat : 6324 (packup2mp4pa-0.) S 6323 6324 4778 34817 4778 4202496 381 0 0 0 0 0 0 0 25 0 1 0 10058069 2633728 275 1283457024 134512640 135304128 4288889952 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/6324/statm: 643 275 233 194 0 30 0
[pid=6325] ppid=6324 vsize=47732 CPUtime=1.5
/proc/6325/stat : 6325 (packup) R 6324 6324 4778 34817 4778 4202496 11488 0 0 0 140 10 0 0 25 0 1 0 10058069 48877568 11367 1283457024 134512640 134752139 4289379488 18446744073709551615 4159228839 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/6325/statm: 11933 11367 316 59 0 11097 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 50304

[startup+3.11288 s]
/proc/loadavg: 1.55 1.18 0.78 2/37 6328
/proc/meminfo: memFree=285400/1048576 swapFree=0/0
[pid=6324] ppid=6323 vsize=2572 CPUtime=0
/proc/6324/stat : 6324 (packup2mp4pa-0.) S 6323 6324 4778 34817 4778 4202496 381 0 0 0 0 0 0 0 25 0 1 0 10058069 2633728 275 1283457024 134512640 135304128 4288889952 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/6324/statm: 643 275 233 194 0 30 0
[pid=6325] ppid=6324 vsize=51048 CPUtime=1.84
/proc/6325/stat : 6325 (packup) S 6324 6324 4778 34817 4778 4202496 12335 0 0 0 162 22 0 0 25 0 1 0 10058069 52273152 12011 1283457024 134512640 134752139 4289379488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/6325/statm: 12762 12011 324 59 0 11926 0
[pid=6327] ppid=6325 vsize=1668 CPUtime=0
/proc/6327/stat : 6327 (sh) S 6325 6324 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 25 0 1 0 10058253 1708032 123 1283457024 134512640 134593992 4287921136 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/6327/statm: 417 123 108 20 0 44 0
[pid=6328] ppid=6327 vsize=29848 CPUtime=1.25
/proc/6328/stat : 6328 (minisatp_32) R 6327 6324 4778 34817 4778 4202496 7095 0 0 0 109 16 0 0 25 0 1 0 10058255 30564352 6322 1283457024 134512640 135413687 4289066272 18446744073709551615 134988446 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/6328/statm: 7462 6322 85 220 0 7240 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 85136

[startup+6.30406 s]
/proc/loadavg: 1.55 1.18 0.78 2/37 6330
/proc/meminfo: memFree=286648/1048576 swapFree=0/0
[pid=6324] ppid=6323 vsize=2572 CPUtime=0
/proc/6324/stat : 6324 (packup2mp4pa-0.) S 6323 6324 4778 34817 4778 4202496 381 0 0 0 0 0 0 0 25 0 1 0 10058069 2633728 275 1283457024 134512640 135304128 4288889952 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/6324/statm: 643 275 233 194 0 30 0
[pid=6325] ppid=6324 vsize=51052 CPUtime=5.23
/proc/6325/stat : 6325 (packup) S 6324 6324 4778 34817 4778 4202496 12412 26021 0 0 181 33 282 27 18 0 1 0 10058069 52277248 12020 1283457024 134512640 134752139 4289379488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/6325/statm: 12763 12020 332 59 0 11927 0
[pid=6329] ppid=6325 vsize=1672 CPUtime=0.01
/proc/6329/stat : 6329 (sh) S 6325 6324 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 18 0 1 0 10058594 1712128 124 1283457024 134512640 134593992 4289324352 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/6329/statm: 418 124 108 20 0 45 0
[pid=6330] ppid=6329 vsize=26840 CPUtime=1.03
/proc/6330/stat : 6330 (minisatp_32) R 6329 6324 4778 34817 4778 4202496 5927 0 0 0 102 1 0 0 24 0 1 0 10058595 27484160 5368 1283457024 134512640 135413687 4294875824 18446744073709551615 134966901 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/6330/statm: 6710 5368 77 220 0 6488 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 82136

[startup+12.7063 s]
/proc/loadavg: 1.46 1.18 0.78 2/37 6330
/proc/meminfo: memFree=116892/1048576 swapFree=0/0
[pid=6324] ppid=6323 vsize=2572 CPUtime=0
/proc/6324/stat : 6324 (packup2mp4pa-0.) S 6323 6324 4778 34817 4778 4202496 381 0 0 0 0 0 0 0 25 0 1 0 10058069 2633728 275 1283457024 134512640 135304128 4288889952 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/6324/statm: 643 275 233 194 0 30 0
[pid=6325] ppid=6324 vsize=51052 CPUtime=5.23
/proc/6325/stat : 6325 (packup) S 6324 6324 4778 34817 4778 4202496 12412 26021 0 0 181 33 282 27 18 0 1 0 10058069 52277248 12020 1283457024 134512640 134752139 4289379488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/6325/statm: 12763 12020 332 59 0 11927 0
[pid=6329] ppid=6325 vsize=1672 CPUtime=0.01
/proc/6329/stat : 6329 (sh) S 6325 6324 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 18 0 1 0 10058594 1712128 124 1283457024 134512640 134593992 4289324352 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/6329/statm: 418 124 108 20 0 45 0
[pid=6330] ppid=6329 vsize=206456 CPUtime=7.42
/proc/6330/stat : 6330 (minisatp_32) R 6329 6324 4778 34817 4778 4202496 63418 0 0 0 710 32 0 0 25 0 1 0 10058595 211410944 46900 1283457024 134512640 135413687 4294875824 18446744073709551615 134688699 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/6330/statm: 51614 46900 107 220 0 51392 0
Current children cumulated CPU time (s) 12.66
Current children cumulated vsize (KiB) 261752

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

[startup+12.8063 s]
/proc/loadavg: 1.46 1.18 0.78 2/37 6330
/proc/meminfo: memFree=116892/1048576 swapFree=0/0
[pid=6324] ppid=6323 vsize=2572 CPUtime=0
/proc/6324/stat : 6324 (packup2mp4pa-0.) S 6323 6324 4778 34817 4778 4202496 381 0 0 0 0 0 0 0 25 0 1 0 10058069 2633728 275 1283457024 134512640 135304128 4288889952 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/6324/statm: 643 275 233 194 0 30 0
[pid=6325] ppid=6324 vsize=51052 CPUtime=5.23
/proc/6325/stat : 6325 (packup) S 6324 6324 4778 34817 4778 4202496 12412 26021 0 0 181 33 282 27 18 0 1 0 10058069 52277248 12020 1283457024 134512640 134752139 4289379488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/6325/statm: 12763 12020 332 59 0 11927 0
[pid=6329] ppid=6325 vsize=1672 CPUtime=0.01
/proc/6329/stat : 6329 (sh) S 6325 6324 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 18 0 1 0 10058594 1712128 124 1283457024 134512640 134593992 4289324352 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/6329/statm: 418 124 108 20 0 45 0
[pid=6330] ppid=6329 vsize=218264 CPUtime=7.52
/proc/6330/stat : 6330 (minisatp_32) R 6329 6324 4778 34817 4778 4202496 63521 0 0 0 720 32 0 0 25 0 1 0 10058595 223502336 47000 1283457024 134512640 135413687 4294875824 18446744073709551615 134698551 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/6330/statm: 54566 47000 107 220 0 54344 0
Current children cumulated CPU time (s) 12.76
Current children cumulated vsize (KiB) 273560

[startup+13.6067 s]
/proc/loadavg: 1.46 1.18 0.78 2/37 6330
/proc/meminfo: memFree=93952/1048576 swapFree=0/0
[pid=6324] ppid=6323 vsize=2572 CPUtime=0
/proc/6324/stat : 6324 (packup2mp4pa-0.) S 6323 6324 4778 34817 4778 4202496 381 0 0 0 0 0 0 0 25 0 1 0 10058069 2633728 275 1283457024 134512640 135304128 4288889952 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/6324/statm: 643 275 233 194 0 30 0
[pid=6325] ppid=6324 vsize=51052 CPUtime=5.23
/proc/6325/stat : 6325 (packup) S 6324 6324 4778 34817 4778 4202496 12412 26021 0 0 181 33 282 27 18 0 1 0 10058069 52277248 12020 1283457024 134512640 134752139 4289379488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/6325/statm: 12763 12020 332 59 0 11927 0
[pid=6329] ppid=6325 vsize=1672 CPUtime=0.01
/proc/6329/stat : 6329 (sh) S 6325 6324 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 18 0 1 0 10058594 1712128 124 1283457024 134512640 134593992 4289324352 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/6329/statm: 418 124 108 20 0 45 0
[pid=6330] ppid=6329 vsize=216712 CPUtime=8.33
/proc/6330/stat : 6330 (minisatp_32) R 6329 6324 4778 34817 4778 4202496 69059 0 0 0 799 34 0 0 25 0 1 0 10058595 221913088 47724 1283457024 134512640 135413687 4294875824 18446744073709551615 134948381 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/6330/statm: 54178 47724 107 220 0 53956 0
Current children cumulated CPU time (s) 13.57
Current children cumulated vsize (KiB) 272008

[startup+14.0068 s]
/proc/loadavg: 1.46 1.18 0.78 2/37 6330
/proc/meminfo: memFree=93952/1048576 swapFree=0/0
[pid=6324] ppid=6323 vsize=2572 CPUtime=0
/proc/6324/stat : 6324 (packup2mp4pa-0.) S 6323 6324 4778 34817 4778 4202496 381 0 0 0 0 0 0 0 25 0 1 0 10058069 2633728 275 1283457024 134512640 135304128 4288889952 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/6324/statm: 643 275 233 194 0 30 0
[pid=6325] ppid=6324 vsize=50280 CPUtime=13.98
/proc/6325/stat : 6325 (packup) R 6324 6324 4778 34817 4778 4202496 15045 95971 0 0 182 38 1112 66 18 0 1 0 10058069 51486720 11839 1283457024 134512640 134752139 4289379488 18446744073709551615 134684884 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/6325/statm: 12570 11839 344 59 0 11734 0
Current children cumulated CPU time (s) 13.98
Current children cumulated vsize (KiB) 52852

Child status: 0
Real time (s): 14.0962
CPU time (s): 14.0729
CPU user time (s): 13.0288
CPU system time (s): 1.04406
CPU usage (%): 99.8342
Max. virtual memory (cumulated for all children) (KiB): 285056

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

runsolver used 0 second user time and 0.008 second system time

The end