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/2c3aece6-c8b2-11df-a040-00163e3d3b7c.cudf.dudf-real.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/dudf-real//2c3aece6-c8b2-11df-a040-00163e3d3b7c.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/2c3aece6-c8b2-11df-a040-00163e3d3b7c.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.24 1.16 1.05 5/36 14948
/proc/meminfo: memFree=406128/1048576 swapFree=0/0
[pid=14947] ppid=14946 vsize=2572 CPUtime=0
/proc/14947/stat : 14947 (packup2mp4tr-0.) R 14946 14947 1511 34817 1511 4202496 360 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 274 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/14947/statm: 643 274 233 194 0 30 0
[pid=14948] ppid=14947 vsize=2572 CPUtime=0
/proc/14948/stat : 14948 (packup2mp4tr-0.) R 14947 14947 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 41 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/14948/statm: 643 41 0 194 0 30 0

[startup+0.115314 s]
/proc/loadavg: 1.24 1.16 1.05 5/36 14948
/proc/meminfo: memFree=406128/1048576 swapFree=0/0
[pid=14947] ppid=14946 vsize=2572 CPUtime=0
/proc/14947/stat : 14947 (packup2mp4tr-0.) S 14946 14947 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 274 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/14947/statm: 643 274 233 194 0 30 0
[pid=14948] ppid=14947 vsize=7668 CPUtime=0.11
/proc/14948/stat : 14948 (packup) R 14947 14947 1511 34817 1511 4202496 1420 0 0 0 10 1 0 0 25 0 1 0 3344525 7852032 1349 1283457024 134512640 134752139 4293709968 18446744073709551615 134681733 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/14948/statm: 1917 1349 286 59 0 1081 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 10240

[startup+0.215332 s]
/proc/loadavg: 1.24 1.16 1.05 5/36 14948
/proc/meminfo: memFree=406128/1048576 swapFree=0/0
[pid=14947] ppid=14946 vsize=2572 CPUtime=0
/proc/14947/stat : 14947 (packup2mp4tr-0.) S 14946 14947 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 274 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/14947/statm: 643 274 233 194 0 30 0
[pid=14948] ppid=14947 vsize=10704 CPUtime=0.21
/proc/14948/stat : 14948 (packup) R 14947 14947 1511 34817 1511 4202496 2180 0 0 0 20 1 0 0 25 0 1 0 3344525 10960896 2109 1283457024 134512640 134752139 4293709968 18446744073709551615 134681826 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/14948/statm: 2676 2109 286 59 0 1840 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 13276

[startup+0.315346 s]
/proc/loadavg: 1.24 1.16 1.05 5/36 14948
/proc/meminfo: memFree=406128/1048576 swapFree=0/0
[pid=14947] ppid=14946 vsize=2572 CPUtime=0
/proc/14947/stat : 14947 (packup2mp4tr-0.) S 14946 14947 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 274 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/14947/statm: 643 274 233 194 0 30 0
[pid=14948] ppid=14947 vsize=13552 CPUtime=0.31
/proc/14948/stat : 14948 (packup) R 14947 14947 1511 34817 1511 4202496 2890 0 0 0 30 1 0 0 25 0 1 0 3344525 13877248 2819 1283457024 134512640 134752139 4293709968 18446744073709551615 4157650358 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/14948/statm: 3388 2819 286 59 0 2552 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 16124

[startup+0.715411 s]
/proc/loadavg: 1.24 1.16 1.05 5/36 14948
/proc/meminfo: memFree=406128/1048576 swapFree=0/0
[pid=14947] ppid=14946 vsize=2572 CPUtime=0
/proc/14947/stat : 14947 (packup2mp4tr-0.) S 14946 14947 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 274 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/14947/statm: 643 274 233 194 0 30 0
[pid=14948] ppid=14947 vsize=23800 CPUtime=0.71
/proc/14948/stat : 14948 (packup) R 14947 14947 1511 34817 1511 4202496 5428 0 0 0 70 1 0 0 25 0 1 0 3344525 24371200 5357 1283457024 134512640 134752139 4293709968 18446744073709551615 134705878 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/14948/statm: 5950 5357 286 59 0 5114 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 26372

[startup+1.51554 s]
/proc/loadavg: 1.24 1.16 1.05 2/37 14949
/proc/meminfo: memFree=372264/1048576 swapFree=0/0
[pid=14947] ppid=14946 vsize=2572 CPUtime=0
/proc/14947/stat : 14947 (packup2mp4tr-0.) S 14946 14947 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 274 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/14947/statm: 643 274 233 194 0 30 0
[pid=14948] ppid=14947 vsize=46776 CPUtime=1.52
/proc/14948/stat : 14948 (packup) R 14947 14947 1511 34817 1511 4202496 11302 0 0 0 134 18 0 0 25 0 1 0 3344525 47898624 11133 1283457024 134512640 134752139 4293709968 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/14948/statm: 11694 11133 321 59 0 10858 0
Current children cumulated CPU time (s) 1.52
Current children cumulated vsize (KiB) 49348

[startup+3.11579 s]
/proc/loadavg: 1.22 1.15 1.05 2/39 14951
/proc/meminfo: memFree=349416/1048576 swapFree=0/0
[pid=14947] ppid=14946 vsize=2572 CPUtime=0
/proc/14947/stat : 14947 (packup2mp4tr-0.) S 14946 14947 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 274 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/14947/statm: 643 274 233 194 0 30 0
[pid=14948] ppid=14947 vsize=49536 CPUtime=3.11
/proc/14948/stat : 14948 (packup) R 14947 14947 1511 34817 1511 4202496 12623 6627 0 0 146 34 117 14 18 0 1 0 3344525 50724864 11597 1283457024 134512640 134752139 4293709968 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/14948/statm: 12384 11597 332 59 0 11548 0
Current children cumulated CPU time (s) 3.11
Current children cumulated vsize (KiB) 52108

[startup+6.30645 s]
/proc/loadavg: 1.22 1.15 1.05 2/38 14953
/proc/meminfo: memFree=297848/1048576 swapFree=0/0
[pid=14947] ppid=14946 vsize=2572 CPUtime=0
/proc/14947/stat : 14947 (packup2mp4tr-0.) S 14946 14947 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 274 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/14947/statm: 643 274 233 194 0 30 0
[pid=14948] ppid=14947 vsize=49540 CPUtime=6.3
/proc/14948/stat : 14948 (packup) R 14947 14947 1511 34817 1511 4202496 12727 29903 0 0 170 64 360 36 18 0 1 0 3344525 50728960 11607 1283457024 134512640 134752139 4293709968 18446744073709551615 4157645865 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/14948/statm: 12385 11607 332 59 0 11549 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 52112

[startup+12.7079 s]
/proc/loadavg: 1.18 1.15 1.05 2/38 14957
/proc/meminfo: memFree=334684/1048576 swapFree=0/0
[pid=14947] ppid=14946 vsize=2572 CPUtime=0
/proc/14947/stat : 14947 (packup2mp4tr-0.) S 14946 14947 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 274 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/14947/statm: 643 274 233 194 0 30 0
[pid=14948] ppid=14947 vsize=49544 CPUtime=10.73
/proc/14948/stat : 14948 (packup) S 14947 14947 1511 34817 1511 4202496 12810 69579 0 0 202 77 738 56 18 0 1 0 3344525 50733056 11608 1283457024 134512640 134752139 4293709968 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/14948/statm: 12386 11608 332 59 0 11550 0
[pid=14956] ppid=14948 vsize=1668 CPUtime=0
/proc/14956/stat : 14956 (sh) S 14948 14947 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 3345601 1708032 123 1283457024 134512640 134593992 4293869968 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14956/statm: 417 123 108 20 0 44 0
[pid=14957] ppid=14956 vsize=94532 CPUtime=1.94
/proc/14957/stat : 14957 (minisatp_32) R 14956 14947 1511 34817 1511 4202496 26912 0 0 0 171 23 0 0 25 0 1 0 3345601 96800768 21201 1283457024 134512640 135413687 4290557584 18446744073709551615 134960702 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/14957/statm: 23633 21201 90 220 0 23411 0
Current children cumulated CPU time (s) 12.67
Current children cumulated vsize (KiB) 148316

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

[startup+12.8079 s]
/proc/loadavg: 1.18 1.15 1.05 2/38 14957
/proc/meminfo: memFree=334684/1048576 swapFree=0/0
[pid=14947] ppid=14946 vsize=2572 CPUtime=0
/proc/14947/stat : 14947 (packup2mp4tr-0.) S 14946 14947 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 274 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/14947/statm: 643 274 233 194 0 30 0
[pid=14948] ppid=14947 vsize=49544 CPUtime=10.73
/proc/14948/stat : 14948 (packup) S 14947 14947 1511 34817 1511 4202496 12810 69579 0 0 202 77 738 56 18 0 1 0 3344525 50733056 11608 1283457024 134512640 134752139 4293709968 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/14948/statm: 12386 11608 332 59 0 11550 0
[pid=14956] ppid=14948 vsize=1668 CPUtime=0
/proc/14956/stat : 14956 (sh) S 14948 14947 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 3345601 1708032 123 1283457024 134512640 134593992 4293869968 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14956/statm: 417 123 108 20 0 44 0
[pid=14957] ppid=14956 vsize=111444 CPUtime=2.04
/proc/14957/stat : 14957 (minisatp_32) R 14956 14947 1511 34817 1511 4202496 30607 0 0 0 179 25 0 0 25 0 1 0 3345601 114118656 23688 1283457024 134512640 135413687 4290557584 18446744073709551615 134692025 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/14957/statm: 27861 23688 92 220 0 27639 0
Current children cumulated CPU time (s) 12.77
Current children cumulated vsize (KiB) 165228

[startup+14.4085 s]
/proc/loadavg: 1.18 1.15 1.05 2/38 14957
/proc/meminfo: memFree=254580/1048576 swapFree=0/0
[pid=14947] ppid=14946 vsize=2572 CPUtime=0
/proc/14947/stat : 14947 (packup2mp4tr-0.) S 14946 14947 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 274 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/14947/statm: 643 274 233 194 0 30 0
[pid=14948] ppid=14947 vsize=49544 CPUtime=10.73
/proc/14948/stat : 14948 (packup) S 14947 14947 1511 34817 1511 4202496 12810 69579 0 0 202 77 738 56 18 0 1 0 3344525 50733056 11608 1283457024 134512640 134752139 4293709968 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/14948/statm: 12386 11608 332 59 0 11550 0
[pid=14956] ppid=14948 vsize=1668 CPUtime=0
/proc/14956/stat : 14956 (sh) S 14948 14947 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 3345601 1708032 123 1283457024 134512640 134593992 4293869968 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14956/statm: 417 123 108 20 0 44 0
[pid=14957] ppid=14956 vsize=119032 CPUtime=3.64
/proc/14957/stat : 14957 (minisatp_32) R 14956 14947 1511 34817 1511 4202496 42187 0 0 0 332 32 0 0 25 0 1 0 3345601 121888768 27450 1283457024 134512640 135413687 4290557584 18446744073709551615 134656344 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/14957/statm: 29758 27450 107 220 0 29536 0
Current children cumulated CPU time (s) 14.37
Current children cumulated vsize (KiB) 172816

[startup+15.2087 s]
/proc/loadavg: 1.18 1.15 1.05 2/38 14957
/proc/meminfo: memFree=254580/1048576 swapFree=0/0
[pid=14947] ppid=14946 vsize=2572 CPUtime=0
/proc/14947/stat : 14947 (packup2mp4tr-0.) S 14946 14947 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 274 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/14947/statm: 643 274 233 194 0 30 0
[pid=14948] ppid=14947 vsize=49544 CPUtime=10.73
/proc/14948/stat : 14948 (packup) S 14947 14947 1511 34817 1511 4202496 12810 69579 0 0 202 77 738 56 18 0 1 0 3344525 50733056 11608 1283457024 134512640 134752139 4293709968 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/14948/statm: 12386 11608 332 59 0 11550 0
[pid=14956] ppid=14948 vsize=1668 CPUtime=0
/proc/14956/stat : 14956 (sh) S 14948 14947 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 3345601 1708032 123 1283457024 134512640 134593992 4293869968 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14956/statm: 417 123 108 20 0 44 0
[pid=14957] ppid=14956 vsize=133908 CPUtime=4.44
/proc/14957/stat : 14957 (minisatp_32) R 14956 14947 1511 34817 1511 4202496 48031 0 0 0 409 35 0 0 25 0 1 0 3345601 137121792 28613 1283457024 134512640 135413687 4290557584 18446744073709551615 134597339 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/14957/statm: 33477 28613 117 220 0 33255 0
Current children cumulated CPU time (s) 15.17
Current children cumulated vsize (KiB) 187692

[startup+15.4088 s]
/proc/loadavg: 1.18 1.15 1.05 2/36 14957
/proc/meminfo: memFree=363484/1048576 swapFree=0/0
[pid=14947] ppid=14946 vsize=2572 CPUtime=0
/proc/14947/stat : 14947 (packup2mp4tr-0.) S 14946 14947 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 3344525 2633728 274 1283457024 134512640 135304128 4293099568 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/14947/statm: 643 274 233 194 0 30 0
[pid=14948] ppid=14947 vsize=44272 CPUtime=15.37
/proc/14948/stat : 14948 (packup) R 14947 14947 1511 34817 1511 4202496 23193 117760 0 0 213 81 1151 92 18 0 1 0 3344525 45334528 10558 1283457024 134512640 134752139 4293709968 18446744073709551615 4157631329 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/14948/statm: 11068 10558 345 59 0 10232 0
Current children cumulated CPU time (s) 15.37
Current children cumulated vsize (KiB) 46844

Child status: 0
Real time (s): 15.4221
CPU time (s): 15.397
CPU user time (s): 13.6449
CPU system time (s): 1.75211
CPU usage (%): 99.8371
Max. virtual memory (cumulated for all children) (KiB): 200568

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

runsolver used 0 second user time and 0 second system time

The end