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/rand348.cudf.s-e-l-s.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/incremental/s-e-l-s/rand348.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/rand348.cudf.s-e-l-s.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.08 1.03 1.00 5/36 11226
/proc/meminfo: memFree=371576/1048576 swapFree=0/0
[pid=11225] ppid=11224 vsize=2572 CPUtime=0
/proc/11225/stat : 11225 (packup2mp4pa-0.) R 11224 11225 4778 34817 4778 4202496 360 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 274 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/11225/statm: 643 274 233 194 0 30 0
[pid=11226] ppid=11225 vsize=2572 CPUtime=0
/proc/11226/stat : 11226 (packup2mp4pa-0.) R 11225 11225 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 41 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/11226/statm: 643 41 0 194 0 30 0

[startup+0.123719 s]
/proc/loadavg: 1.08 1.03 1.00 5/36 11226
/proc/meminfo: memFree=371576/1048576 swapFree=0/0
[pid=11225] ppid=11224 vsize=2572 CPUtime=0
/proc/11225/stat : 11225 (packup2mp4pa-0.) S 11224 11225 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 274 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11225/statm: 643 274 233 194 0 30 0
[pid=11226] ppid=11225 vsize=8420 CPUtime=0.12
/proc/11226/stat : 11226 (packup) R 11225 11225 4778 34817 4778 4202496 1593 0 0 0 12 0 0 0 25 0 1 0 10559805 8622080 1522 1283457024 134512640 134752139 4291393168 18446744073709551615 134681672 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/11226/statm: 2105 1522 286 59 0 1269 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 10992

[startup+0.213742 s]
/proc/loadavg: 1.08 1.03 1.00 5/36 11226
/proc/meminfo: memFree=371576/1048576 swapFree=0/0
[pid=11225] ppid=11224 vsize=2572 CPUtime=0
/proc/11225/stat : 11225 (packup2mp4pa-0.) S 11224 11225 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 274 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11225/statm: 643 274 233 194 0 30 0
[pid=11226] ppid=11225 vsize=11720 CPUtime=0.2
/proc/11226/stat : 11226 (packup) R 11225 11225 4778 34817 4778 4202496 2423 0 0 0 20 0 0 0 25 0 1 0 10559805 12001280 2352 1283457024 134512640 134752139 4291393168 18446744073709551615 4157249271 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/11226/statm: 2930 2352 286 59 0 2094 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 14292

[startup+0.303762 s]
/proc/loadavg: 1.08 1.03 1.00 5/36 11226
/proc/meminfo: memFree=371576/1048576 swapFree=0/0
[pid=11225] ppid=11224 vsize=2572 CPUtime=0
/proc/11225/stat : 11225 (packup2mp4pa-0.) S 11224 11225 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 274 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11225/statm: 643 274 233 194 0 30 0
[pid=11226] ppid=11225 vsize=14688 CPUtime=0.3
/proc/11226/stat : 11226 (packup) R 11225 11225 4778 34817 4778 4202496 3149 0 0 0 30 0 0 0 25 0 1 0 10559805 15040512 3078 1283457024 134512640 134752139 4291393168 18446744073709551615 134707236 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/11226/statm: 3672 3078 286 59 0 2836 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 17260

[startup+0.703833 s]
/proc/loadavg: 1.08 1.03 1.00 5/36 11226
/proc/meminfo: memFree=371576/1048576 swapFree=0/0
[pid=11225] ppid=11224 vsize=2572 CPUtime=0
/proc/11225/stat : 11225 (packup2mp4pa-0.) S 11224 11225 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 274 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11225/statm: 643 274 233 194 0 30 0
[pid=11226] ppid=11225 vsize=25988 CPUtime=0.69
/proc/11226/stat : 11226 (packup) R 11225 11225 4778 34817 4778 4202496 5993 0 0 0 68 1 0 0 25 0 1 0 10559805 26611712 5922 1283457024 134512640 134752139 4291393168 18446744073709551615 4157250740 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/11226/statm: 6497 5922 286 59 0 5661 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 28560

[startup+1.504 s]
/proc/loadavg: 1.08 1.03 1.00 2/37 11228
/proc/meminfo: memFree=338952/1048576 swapFree=0/0
[pid=11225] ppid=11224 vsize=2572 CPUtime=0
/proc/11225/stat : 11225 (packup2mp4pa-0.) S 11224 11225 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 274 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11225/statm: 643 274 233 194 0 30 0
[pid=11226] ppid=11225 vsize=56604 CPUtime=1.48
/proc/11226/stat : 11226 (packup) R 11225 11225 4778 34817 4778 4202496 13494 0 0 0 142 6 0 0 25 0 1 0 10559805 57962496 13374 1283457024 134512640 134752139 4291393168 18446744073709551615 4157244707 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/11226/statm: 14151 13374 319 59 0 13315 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 59176

[startup+3.10441 s]
/proc/loadavg: 1.08 1.03 1.00 2/39 11230
/proc/meminfo: memFree=309284/1048576 swapFree=0/0
[pid=11225] ppid=11224 vsize=2572 CPUtime=0
/proc/11225/stat : 11225 (packup2mp4pa-0.) S 11224 11225 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 274 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11225/statm: 643 274 233 194 0 30 0
[pid=11226] ppid=11225 vsize=55708 CPUtime=1.81
/proc/11226/stat : 11226 (packup) S 11225 11225 4778 34817 4778 4202496 13501 0 0 0 155 26 0 0 25 0 1 0 10559805 57044992 13156 1283457024 134512640 134752139 4291393168 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/11226/statm: 13927 13156 324 59 0 13091 0
[pid=11229] ppid=11226 vsize=1676 CPUtime=0
/proc/11229/stat : 11229 (sh) S 11226 11225 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 25 0 1 0 10559986 1716224 124 1283457024 134512640 134593992 4287411056 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/11229/statm: 419 124 108 20 0 46 0
[pid=11230] ppid=11229 vsize=28888 CPUtime=1.27
/proc/11230/stat : 11230 (minisatp_32) R 11229 11225 4778 34817 4778 4202496 6842 0 0 0 115 12 0 0 25 0 1 0 10559988 29581312 6119 1283457024 134512640 135413687 4287286128 18446744073709551615 134696978 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/11230/statm: 7222 6119 89 220 0 7000 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 88844

[startup+6.30596 s]
/proc/loadavg: 1.07 1.03 1.00 2/39 11232
/proc/meminfo: memFree=284740/1048576 swapFree=0/0
[pid=11225] ppid=11224 vsize=2572 CPUtime=0
/proc/11225/stat : 11225 (packup2mp4pa-0.) S 11224 11225 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 274 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11225/statm: 643 274 233 194 0 30 0
[pid=11226] ppid=11225 vsize=55712 CPUtime=3.92
/proc/11226/stat : 11226 (packup) S 11225 11225 4778 34817 4778 4202496 13563 11021 0 0 167 44 167 14 18 0 1 0 10559805 57049088 13165 1283457024 134512640 134752139 4291393168 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/11226/statm: 13928 13165 332 59 0 13092 0
[pid=11231] ppid=11226 vsize=1668 CPUtime=0.01
/proc/11231/stat : 11231 (sh) S 11226 11225 4778 34817 4778 4202496 145 0 0 0 0 1 0 0 18 0 1 0 10560201 1708032 123 1283457024 134512640 134593992 4289170720 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/11231/statm: 417 123 108 20 0 44 0
[pid=11232] ppid=11231 vsize=84504 CPUtime=2.32
/proc/11232/stat : 11232 (minisatp_32) R 11231 11225 4778 34817 4778 4202496 24184 0 0 0 210 22 0 0 25 0 1 0 10560202 86532096 18091 1283457024 134512640 135413687 4289518992 18446744073709551615 134686238 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/11232/statm: 21126 18091 107 220 0 20904 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 144456

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

[startup+6.40598 s]
/proc/loadavg: 1.07 1.03 1.00 2/39 11232
/proc/meminfo: memFree=284740/1048576 swapFree=0/0
[pid=11225] ppid=11224 vsize=2572 CPUtime=0
/proc/11225/stat : 11225 (packup2mp4pa-0.) S 11224 11225 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 274 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11225/statm: 643 274 233 194 0 30 0
[pid=11226] ppid=11225 vsize=55712 CPUtime=3.92
/proc/11226/stat : 11226 (packup) S 11225 11225 4778 34817 4778 4202496 13563 11021 0 0 167 44 167 14 18 0 1 0 10559805 57049088 13165 1283457024 134512640 134752139 4291393168 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/11226/statm: 13928 13165 332 59 0 13092 0
[pid=11231] ppid=11226 vsize=1668 CPUtime=0.01
/proc/11231/stat : 11231 (sh) S 11226 11225 4778 34817 4778 4202496 145 0 0 0 0 1 0 0 18 0 1 0 10560201 1708032 123 1283457024 134512640 134593992 4289170720 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/11231/statm: 417 123 108 20 0 44 0
[pid=11232] ppid=11231 vsize=88168 CPUtime=2.42
/proc/11232/stat : 11232 (minisatp_32) R 11231 11225 4778 34817 4778 4202496 25223 0 0 0 220 22 0 0 25 0 1 0 10560202 90284032 19097 1283457024 134512640 135413687 4289518992 18446744073709551615 134689982 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/11232/statm: 22042 19097 107 220 0 21820 0
Current children cumulated CPU time (s) 6.35
Current children cumulated vsize (KiB) 148120

[startup+8.00645 s]
/proc/loadavg: 1.07 1.03 1.00 2/39 11232
/proc/meminfo: memFree=210588/1048576 swapFree=0/0
[pid=11225] ppid=11224 vsize=2572 CPUtime=0
/proc/11225/stat : 11225 (packup2mp4pa-0.) S 11224 11225 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 274 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11225/statm: 643 274 233 194 0 30 0
[pid=11226] ppid=11225 vsize=55712 CPUtime=3.92
/proc/11226/stat : 11226 (packup) S 11225 11225 4778 34817 4778 4202496 13563 11021 0 0 167 44 167 14 18 0 1 0 10559805 57049088 13165 1283457024 134512640 134752139 4291393168 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/11226/statm: 13928 13165 332 59 0 13092 0
[pid=11231] ppid=11226 vsize=1668 CPUtime=0.01
/proc/11231/stat : 11231 (sh) S 11226 11225 4778 34817 4778 4202496 145 0 0 0 0 1 0 0 18 0 1 0 10560201 1708032 123 1283457024 134512640 134593992 4289170720 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/11231/statm: 417 123 108 20 0 44 0
[pid=11232] ppid=11231 vsize=123260 CPUtime=4.03
/proc/11232/stat : 11232 (minisatp_32) R 11231 11225 4778 34817 4778 4202496 37876 0 0 0 374 29 0 0 25 0 1 0 10560202 126218240 27712 1283457024 134512640 135413687 4289518992 18446744073709551615 134696685 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/11232/statm: 30815 27712 107 220 0 30593 0
Current children cumulated CPU time (s) 7.96
Current children cumulated vsize (KiB) 183212

[startup+8.80669 s]
/proc/loadavg: 1.07 1.03 1.00 2/39 11232
/proc/meminfo: memFree=197196/1048576 swapFree=0/0
[pid=11225] ppid=11224 vsize=2572 CPUtime=0
/proc/11225/stat : 11225 (packup2mp4pa-0.) S 11224 11225 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 274 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11225/statm: 643 274 233 194 0 30 0
[pid=11226] ppid=11225 vsize=55712 CPUtime=3.92
/proc/11226/stat : 11226 (packup) S 11225 11225 4778 34817 4778 4202496 13563 11021 0 0 167 44 167 14 18 0 1 0 10559805 57049088 13165 1283457024 134512640 134752139 4291393168 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/11226/statm: 13928 13165 332 59 0 13092 0
[pid=11231] ppid=11226 vsize=1668 CPUtime=0.01
/proc/11231/stat : 11231 (sh) S 11226 11225 4778 34817 4778 4202496 145 0 0 0 0 1 0 0 18 0 1 0 10560201 1708032 123 1283457024 134512640 134593992 4289170720 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/11231/statm: 417 123 108 20 0 44 0
[pid=11232] ppid=11231 vsize=137276 CPUtime=4.82
/proc/11232/stat : 11232 (minisatp_32) R 11231 11225 4778 34817 4778 4202496 43329 0 0 0 450 32 0 0 25 0 1 0 10560202 140570624 30067 1283457024 134512640 135413687 4289518992 18446744073709551615 134948489 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/11232/statm: 34319 30067 108 220 0 34097 0
Current children cumulated CPU time (s) 8.75
Current children cumulated vsize (KiB) 197228

[startup+9.60693 s]
/proc/loadavg: 1.07 1.03 1.00 2/39 11232
/proc/meminfo: memFree=197196/1048576 swapFree=0/0
[pid=11225] ppid=11224 vsize=2572 CPUtime=0
/proc/11225/stat : 11225 (packup2mp4pa-0.) S 11224 11225 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 274 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11225/statm: 643 274 233 194 0 30 0
[pid=11226] ppid=11225 vsize=55712 CPUtime=3.92
/proc/11226/stat : 11226 (packup) S 11225 11225 4778 34817 4778 4202496 13563 11021 0 0 167 44 167 14 18 0 1 0 10559805 57049088 13165 1283457024 134512640 134752139 4291393168 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/11226/statm: 13928 13165 332 59 0 13092 0
[pid=11231] ppid=11226 vsize=1668 CPUtime=0.01
/proc/11231/stat : 11231 (sh) S 11226 11225 4778 34817 4778 4202496 145 0 0 0 0 1 0 0 18 0 1 0 10560201 1708032 123 1283457024 134512640 134593992 4289170720 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/11231/statm: 417 123 108 20 0 44 0
[pid=11232] ppid=11231 vsize=149360 CPUtime=5.63
/proc/11232/stat : 11232 (minisatp_32) R 11231 11225 4778 34817 4778 4202496 50372 0 0 0 527 36 0 0 25 0 1 0 10560202 152944640 33432 1283457024 134512640 135413687 4289518992 18446744073709551615 134698760 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/11232/statm: 37340 33432 107 220 0 37118 0
Current children cumulated CPU time (s) 9.56
Current children cumulated vsize (KiB) 209312

[startup+10.0071 s]
/proc/loadavg: 1.07 1.03 1.00 2/39 11232
/proc/meminfo: memFree=189508/1048576 swapFree=0/0
[pid=11225] ppid=11224 vsize=2572 CPUtime=0
/proc/11225/stat : 11225 (packup2mp4pa-0.) S 11224 11225 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 25 0 1 0 10559805 2633728 274 1283457024 134512640 135304128 4289375440 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/11225/statm: 643 274 233 194 0 30 0
[pid=11226] ppid=11225 vsize=54940 CPUtime=9.97
/proc/11226/stat : 11226 (packup) R 11225 11225 4778 34817 4778 4202496 17693 61555 0 0 170 46 729 52 18 0 1 0 10559805 56258560 12984 1283457024 134512640 134752139 4291393168 18446744073709551615 4159041732 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/11226/statm: 13735 12984 344 59 0 12899 0
Current children cumulated CPU time (s) 9.97
Current children cumulated vsize (KiB) 57512

Child status: 0
Real time (s): 10.1007
CPU time (s): 10.0846
CPU user time (s): 9.07257
CPU system time (s): 1.01206
CPU usage (%): 99.841
Max. virtual memory (cumulated for all children) (KiB): 227292

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

runsolver used 0 second user time and 0.012 second system time

The end