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/201108241238/packup2mp4tr-0.6/fe523ea6-9b1b-11df-bc37-00163e46d37a.cudf.dudf-real.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/dudf-real//fe523ea6-9b1b-11df-bc37-00163e46d37a.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/fe523ea6-9b1b-11df-bc37-00163e46d37a.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.34 1.27 1.16 4/36 3012
/proc/meminfo: memFree=284476/1048576 swapFree=0/0
[pid=3011] ppid=3010 vsize=2568 CPUtime=0
/proc/3011/stat : 3011 (packup2mp4tr-0.) S 3010 3011 1511 34817 1511 4202496 376 0 0 0 0 0 0 0 18 0 1 0 5227475 2629632 273 1283457024 134512640 135304128 4294324576 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3011/statm: 642 273 233 194 0 29 0
[pid=3012] ppid=3011 vsize=3712 CPUtime=0
/proc/3012/stat : 3012 (packup) R 3011 3011 1511 34817 1511 4202496 412 0 0 0 0 0 0 0 25 0 1 0 5227475 3801088 341 1283457024 134512640 134752139 4294896048 18446744073709551615 4157705384 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/3012/statm: 928 341 286 59 0 92 0

[startup+0.1646 s]
/proc/loadavg: 1.34 1.27 1.16 4/36 3012
/proc/meminfo: memFree=284476/1048576 swapFree=0/0
[pid=3011] ppid=3010 vsize=2568 CPUtime=0
/proc/3011/stat : 3011 (packup2mp4tr-0.) S 3010 3011 1511 34817 1511 4202496 376 0 0 0 0 0 0 0 18 0 1 0 5227475 2629632 273 1283457024 134512640 135304128 4294324576 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3011/statm: 642 273 233 194 0 29 0
[pid=3012] ppid=3011 vsize=9304 CPUtime=0.16
/proc/3012/stat : 3012 (packup) R 3011 3011 1511 34817 1511 4202496 1807 0 0 0 16 0 0 0 25 0 1 0 5227475 9527296 1736 1283457024 134512640 134752139 4294896048 18446744073709551615 134681676 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/3012/statm: 2326 1736 286 59 0 1490 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 11872

[startup+0.204607 s]
/proc/loadavg: 1.34 1.27 1.16 4/36 3012
/proc/meminfo: memFree=284476/1048576 swapFree=0/0
[pid=3011] ppid=3010 vsize=2568 CPUtime=0
/proc/3011/stat : 3011 (packup2mp4tr-0.) S 3010 3011 1511 34817 1511 4202496 376 0 0 0 0 0 0 0 18 0 1 0 5227475 2629632 273 1283457024 134512640 135304128 4294324576 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3011/statm: 642 273 233 194 0 29 0
[pid=3012] ppid=3011 vsize=10492 CPUtime=0.2
/proc/3012/stat : 3012 (packup) R 3011 3011 1511 34817 1511 4202496 2109 0 0 0 18 2 0 0 25 0 1 0 5227475 10743808 2038 1283457024 134512640 134752139 4294896048 18446744073709551615 134681493 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/3012/statm: 2623 2038 286 59 0 1787 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13060

[startup+0.304623 s]
/proc/loadavg: 1.34 1.27 1.16 4/36 3012
/proc/meminfo: memFree=284476/1048576 swapFree=0/0
[pid=3011] ppid=3010 vsize=2568 CPUtime=0
/proc/3011/stat : 3011 (packup2mp4tr-0.) S 3010 3011 1511 34817 1511 4202496 376 0 0 0 0 0 0 0 18 0 1 0 5227475 2629632 273 1283457024 134512640 135304128 4294324576 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3011/statm: 642 273 233 194 0 29 0
[pid=3012] ppid=3011 vsize=13392 CPUtime=0.3
/proc/3012/stat : 3012 (packup) R 3011 3011 1511 34817 1511 4202496 2823 0 0 0 28 2 0 0 25 0 1 0 5227475 13713408 2752 1283457024 134512640 134752139 4294896048 18446744073709551615 134681767 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/3012/statm: 3348 2752 286 59 0 2512 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15960

[startup+0.7047 s]
/proc/loadavg: 1.34 1.27 1.16 4/36 3012
/proc/meminfo: memFree=284476/1048576 swapFree=0/0
[pid=3011] ppid=3010 vsize=2568 CPUtime=0
/proc/3011/stat : 3011 (packup2mp4tr-0.) S 3010 3011 1511 34817 1511 4202496 376 0 0 0 0 0 0 0 18 0 1 0 5227475 2629632 273 1283457024 134512640 135304128 4294324576 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3011/statm: 642 273 233 194 0 29 0
[pid=3012] ppid=3011 vsize=23356 CPUtime=0.7
/proc/3012/stat : 3012 (packup) R 3011 3011 1511 34817 1511 4202496 5314 0 0 0 66 4 0 0 25 0 1 0 5227475 23916544 5243 1283457024 134512640 134752139 4294896048 18446744073709551615 4157692184 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/3012/statm: 5839 5243 286 59 0 5003 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 25924

[startup+1.50489 s]
/proc/loadavg: 1.34 1.27 1.16 2/37 3013
/proc/meminfo: memFree=251844/1048576 swapFree=0/0
[pid=3011] ppid=3010 vsize=2568 CPUtime=0
/proc/3011/stat : 3011 (packup2mp4tr-0.) S 3010 3011 1511 34817 1511 4202496 376 0 0 0 0 0 0 0 18 0 1 0 5227475 2629632 273 1283457024 134512640 135304128 4294324576 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3011/statm: 642 273 233 194 0 29 0
[pid=3012] ppid=3011 vsize=35788 CPUtime=1.21
/proc/3012/stat : 3012 (packup) S 3011 3011 1511 34817 1511 4202496 8466 0 0 0 106 15 0 0 25 0 1 0 5227475 36646912 8394 1283457024 134512640 134752139 4294896048 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/3012/statm: 8947 8394 324 59 0 8111 0
Current children cumulated CPU time (s) 1.21
Current children cumulated vsize (KiB) 38356

[startup+3.10542 s]
/proc/loadavg: 1.34 1.27 1.16 2/39 3017
/proc/meminfo: memFree=247720/1048576 swapFree=0/0
[pid=3011] ppid=3010 vsize=2568 CPUtime=0
/proc/3011/stat : 3011 (packup2mp4tr-0.) S 3010 3011 1511 34817 1511 4202496 376 0 0 0 0 0 0 0 18 0 1 0 5227475 2629632 273 1283457024 134512640 135304128 4294324576 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3011/statm: 642 273 233 194 0 29 0
[pid=3012] ppid=3011 vsize=37212 CPUtime=2.11
/proc/3012/stat : 3012 (packup) S 3011 3011 1511 34817 1511 4202496 9092 4574 0 0 114 25 62 10 19 0 1 0 5227475 38105088 8630 1283457024 134512640 134752139 4294896048 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/3012/statm: 9303 8630 332 59 0 8467 0
[pid=3016] ppid=3012 vsize=1676 CPUtime=0
/proc/3016/stat : 3016 (sh) S 3012 3011 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 19 0 1 0 5227688 1716224 124 1283457024 134512640 134593992 4288918752 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/3016/statm: 419 124 108 20 0 46 0
[pid=3017] ppid=3016 vsize=35080 CPUtime=0.96
/proc/3017/stat : 3017 (minisatp_32) R 3016 3011 1511 34817 1511 4202496 10478 0 0 0 88 8 0 0 25 0 1 0 5227688 35921920 7946 1283457024 134512640 135413687 4287366016 18446744073709551615 134686526 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/3017/statm: 8770 7946 108 220 0 8548 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 76536

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

[startup+3.20544 s]
/proc/loadavg: 1.34 1.27 1.16 2/39 3017
/proc/meminfo: memFree=247720/1048576 swapFree=0/0
[pid=3011] ppid=3010 vsize=2568 CPUtime=0
/proc/3011/stat : 3011 (packup2mp4tr-0.) S 3010 3011 1511 34817 1511 4202496 376 0 0 0 0 0 0 0 18 0 1 0 5227475 2629632 273 1283457024 134512640 135304128 4294324576 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3011/statm: 642 273 233 194 0 29 0
[pid=3012] ppid=3011 vsize=37212 CPUtime=2.11
/proc/3012/stat : 3012 (packup) S 3011 3011 1511 34817 1511 4202496 9092 4574 0 0 114 25 62 10 19 0 1 0 5227475 38105088 8630 1283457024 134512640 134752139 4294896048 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/3012/statm: 9303 8630 332 59 0 8467 0
[pid=3016] ppid=3012 vsize=1676 CPUtime=0
/proc/3016/stat : 3016 (sh) S 3012 3011 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 19 0 1 0 5227688 1716224 124 1283457024 134512640 134593992 4288918752 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/3016/statm: 419 124 108 20 0 46 0
[pid=3017] ppid=3016 vsize=41952 CPUtime=1.07
/proc/3017/stat : 3017 (minisatp_32) R 3016 3011 1511 34817 1511 4202496 11667 0 0 0 97 10 0 0 25 0 1 0 5227688 42958848 8840 1283457024 134512640 135413687 4287366016 18446744073709551615 134688103 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/3017/statm: 10488 8840 108 220 0 10266 0
Current children cumulated CPU time (s) 3.18
Current children cumulated vsize (KiB) 83408

[startup+4.80571 s]
/proc/loadavg: 1.31 1.26 1.16 2/39 3019
/proc/meminfo: memFree=234948/1048576 swapFree=0/0
[pid=3011] ppid=3010 vsize=2568 CPUtime=0
/proc/3011/stat : 3011 (packup2mp4tr-0.) S 3010 3011 1511 34817 1511 4202496 376 0 0 0 0 0 0 0 18 0 1 0 5227475 2629632 273 1283457024 134512640 135304128 4294324576 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3011/statm: 642 273 233 194 0 29 0
[pid=3012] ppid=3011 vsize=37220 CPUtime=4.61
/proc/3012/stat : 3012 (packup) S 3011 3011 1511 34817 1511 4202496 9211 22452 0 0 128 48 258 27 16 0 1 0 5227475 38113280 8637 1283457024 134512640 134752139 4294896048 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/3012/statm: 9305 8637 332 59 0 8469 0
Current children cumulated CPU time (s) 4.61
Current children cumulated vsize (KiB) 39788

[startup+5.60583 s]
/proc/loadavg: 1.31 1.26 1.16 2/39 3021
/proc/meminfo: memFree=226268/1048576 swapFree=0/0
[pid=3011] ppid=3010 vsize=2568 CPUtime=0
/proc/3011/stat : 3011 (packup2mp4tr-0.) S 3010 3011 1511 34817 1511 4202496 376 0 0 0 0 0 0 0 18 0 1 0 5227475 2629632 273 1283457024 134512640 135304128 4294324576 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3011/statm: 642 273 233 194 0 29 0
[pid=3012] ppid=3011 vsize=37220 CPUtime=4.61
/proc/3012/stat : 3012 (packup) S 3011 3011 1511 34817 1511 4202496 9211 22452 0 0 128 48 258 27 16 0 1 0 5227475 38113280 8637 1283457024 134512640 134752139 4294896048 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/3012/statm: 9305 8637 332 59 0 8469 0
[pid=3020] ppid=3012 vsize=1672 CPUtime=0
/proc/3020/stat : 3020 (sh) S 3012 3011 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 16 0 1 0 5227938 1712128 124 1283457024 134512640 134593992 4290401872 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/3020/statm: 418 124 108 20 0 45 0
[pid=3021] ppid=3020 vsize=33328 CPUtime=0.97
/proc/3021/stat : 3021 (minisatp_32) R 3020 3011 1511 34817 1511 4202496 9373 0 0 0 91 6 0 0 20 0 1 0 5227939 34127872 7443 1283457024 134512640 135413687 4292434000 18446744073709551615 134688784 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/3021/statm: 8332 7443 108 220 0 8110 0
Current children cumulated CPU time (s) 5.58
Current children cumulated vsize (KiB) 74788

[startup+6.00591 s]
/proc/loadavg: 1.31 1.26 1.16 2/39 3021
/proc/meminfo: memFree=226268/1048576 swapFree=0/0
[pid=3011] ppid=3010 vsize=2568 CPUtime=0
/proc/3011/stat : 3011 (packup2mp4tr-0.) S 3010 3011 1511 34817 1511 4202496 376 0 0 0 0 0 0 0 18 0 1 0 5227475 2629632 273 1283457024 134512640 135304128 4294324576 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3011/statm: 642 273 233 194 0 29 0
[pid=3012] ppid=3011 vsize=37220 CPUtime=4.61
/proc/3012/stat : 3012 (packup) S 3011 3011 1511 34817 1511 4202496 9211 22452 0 0 128 48 258 27 16 0 1 0 5227475 38113280 8637 1283457024 134512640 134752139 4294896048 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/3012/statm: 9305 8637 332 59 0 8469 0
[pid=3020] ppid=3012 vsize=1672 CPUtime=0
/proc/3020/stat : 3020 (sh) S 3012 3011 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 16 0 1 0 5227938 1712128 124 1283457024 134512640 134593992 4290401872 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/3020/statm: 418 124 108 20 0 45 0
[pid=3021] ppid=3020 vsize=38288 CPUtime=1.36
/proc/3021/stat : 3021 (minisatp_32) R 3020 3011 1511 34817 1511 4202496 12373 0 0 0 128 8 0 0 21 0 1 0 5227939 39206912 8469 1283457024 134512640 135413687 4292434000 18446744073709551615 134753040 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/3021/statm: 9572 8469 108 220 0 9350 0
Current children cumulated CPU time (s) 5.97
Current children cumulated vsize (KiB) 79748

[startup+6.21599 s]
/proc/loadavg: 1.31 1.26 1.16 2/39 3021
/proc/meminfo: memFree=226268/1048576 swapFree=0/0
[pid=3011] ppid=3010 vsize=2568 CPUtime=0
/proc/3011/stat : 3011 (packup2mp4tr-0.) S 3010 3011 1511 34817 1511 4202496 376 0 0 0 0 0 0 0 18 0 1 0 5227475 2629632 273 1283457024 134512640 135304128 4294324576 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3011/statm: 642 273 233 194 0 29 0
[pid=3012] ppid=3011 vsize=36832 CPUtime=6.19
/proc/3012/stat : 3012 (packup) R 3011 3011 1511 34817 1511 4202496 12308 35203 0 0 130 50 403 36 15 0 1 0 5227475 37715968 8553 1283457024 134512640 134752139 4294896048 18446744073709551615 4157700334 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/3012/statm: 9208 8553 345 59 0 8372 0
Current children cumulated CPU time (s) 6.19
Current children cumulated vsize (KiB) 39400

Child status: 0
Real time (s): 6.28024
CPU time (s): 6.27639
CPU user time (s): 5.39234
CPU system time (s): 0.884055
CPU usage (%): 99.9388
Max. virtual memory (cumulated for all children) (KiB): 83408

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 5.39234
system time used= 0.884055
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 52754
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= 19
involuntary context switches= 117

runsolver used 0 second user time and 0 second system time

The end