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/4a69cf16-c731-11df-9182-00163e3d3b7c.cudf.dudf-real.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/dudf-real//4a69cf16-c731-11df-9182-00163e3d3b7c.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/4a69cf16-c731-11df-9182-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.30 1.29 1.12 5/36 21857
/proc/meminfo: memFree=365512/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=3976 CPUtime=0.01
/proc/21857/stat : 21857 (packup) R 21856 21856 1511 34817 1511 4202496 490 0 0 0 1 0 0 0 25 0 1 0 4625934 4071424 419 1283457024 134512640 134752139 4294463824 18446744073709551615 134681826 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/21857/statm: 994 419 286 59 0 158 0

[startup+0.192983 s]
/proc/loadavg: 1.30 1.29 1.12 5/36 21857
/proc/meminfo: memFree=365512/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=10064 CPUtime=0.19
/proc/21857/stat : 21857 (packup) R 21856 21856 1511 34817 1511 4202496 2005 0 0 0 19 0 0 0 25 0 1 0 4625934 10305536 1934 1283457024 134512640 134752139 4294463824 18446744073709551615 134696213 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/21857/statm: 2516 1934 286 59 0 1680 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 12636

[startup+0.202981 s]
/proc/loadavg: 1.30 1.29 1.12 5/36 21857
/proc/meminfo: memFree=365512/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=10328 CPUtime=0.2
/proc/21857/stat : 21857 (packup) R 21856 21856 1511 34817 1511 4202496 2083 0 0 0 20 0 0 0 25 0 1 0 4625934 10575872 2012 1283457024 134512640 134752139 4294463824 18446744073709551615 4159013106 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/21857/statm: 2582 2012 286 59 0 1746 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12900

[startup+0.313001 s]
/proc/loadavg: 1.30 1.29 1.12 5/36 21857
/proc/meminfo: memFree=365512/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=13480 CPUtime=0.31
/proc/21857/stat : 21857 (packup) R 21856 21856 1511 34817 1511 4202496 2846 0 0 0 31 0 0 0 25 0 1 0 4625934 13803520 2775 1283457024 134512640 134752139 4294463824 18446744073709551615 134681211 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/21857/statm: 3370 2775 286 59 0 2534 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 16052

[startup+0.713062 s]
/proc/loadavg: 1.30 1.29 1.12 5/36 21857
/proc/meminfo: memFree=365512/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=23460 CPUtime=0.7
/proc/21857/stat : 21857 (packup) R 21856 21856 1511 34817 1511 4202496 5351 0 0 0 70 0 0 0 25 0 1 0 4625934 24023040 5280 1283457024 134512640 134752139 4294463824 18446744073709551615 134681672 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/21857/statm: 5865 5280 286 59 0 5029 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 26032

[startup+1.51318 s]
/proc/loadavg: 1.30 1.29 1.12 2/37 21858
/proc/meminfo: memFree=334128/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=50828 CPUtime=1.5
/proc/21857/stat : 21857 (packup) R 21856 21856 1511 34817 1511 4202496 12352 0 0 0 144 6 0 0 25 0 1 0 4625934 52047872 11935 1283457024 134512640 134752139 4294463824 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/21857/statm: 12707 11935 322 59 0 11871 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 53400

[startup+3.11175 s]
/proc/loadavg: 1.30 1.29 1.12 2/39 21860
/proc/meminfo: memFree=307684/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=50828 CPUtime=1.75
/proc/21857/stat : 21857 (packup) S 21856 21856 1511 34817 1511 4202496 12357 0 0 0 152 23 0 0 25 0 1 0 4625934 52047872 11938 1283457024 134512640 134752139 4294463824 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/21857/statm: 12707 11938 325 59 0 11871 0
[pid=21859] ppid=21857 vsize=1672 CPUtime=0
/proc/21859/stat : 21859 (sh) S 21857 21856 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 25 0 1 0 4626119 1712128 124 1283457024 134512640 134593992 4289721760 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/21859/statm: 418 124 108 20 0 45 0
[pid=21860] ppid=21859 vsize=30892 CPUtime=1.24
/proc/21860/stat : 21860 (minisatp_32) R 21859 21856 1511 34817 1511 4202496 7040 0 0 0 122 2 0 0 25 0 1 0 4626120 31633408 6364 1283457024 134512640 135413687 4294339104 18446744073709551615 134960688 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/21860/statm: 7723 6364 77 220 0 7501 0
Current children cumulated CPU time (s) 2.99
Current children cumulated vsize (KiB) 85964

[startup+6.31253 s]
/proc/loadavg: 1.28 1.28 1.12 2/37 21860
/proc/meminfo: memFree=316280/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=50832 CPUtime=5.48
/proc/21857/stat : 21857 (packup) S 21856 21856 1511 34817 1511 4202496 12453 27804 0 0 170 43 306 29 18 0 1 0 4625934 52051968 11957 1283457024 134512640 134752139 4294463824 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/21857/statm: 12708 11957 333 59 0 11872 0
Current children cumulated CPU time (s) 5.48
Current children cumulated vsize (KiB) 53404

[startup+12.7081 s]
/proc/loadavg: 1.25 1.28 1.12 2/39 21863
/proc/meminfo: memFree=131116/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=50832 CPUtime=5.48
/proc/21857/stat : 21857 (packup) S 21856 21856 1511 34817 1511 4202496 12453 27804 0 0 170 43 306 29 18 0 1 0 4625934 52051968 11957 1283457024 134512640 134752139 4294463824 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/21857/statm: 12708 11957 333 59 0 11872 0
[pid=21861] ppid=21857 vsize=1672 CPUtime=0
/proc/21861/stat : 21861 (sh) S 21857 21856 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 4626493 1712128 124 1283457024 134512640 134593992 4293425456 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/21861/statm: 418 124 108 20 0 45 0
[pid=21862] ppid=21861 vsize=197308 CPUtime=7.07
/proc/21862/stat : 21862 (minisatp_32) R 21861 21856 1511 34817 1511 4202496 65622 0 0 0 665 42 0 0 25 0 1 0 4626494 202043392 44313 1283457024 134512640 135413687 4287101760 18446744073709551615 134705617 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/21862/statm: 49327 44313 107 220 0 49105 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 252384

[startup+25.5113 s]
/proc/loadavg: 1.20 1.26 1.12 2/39 21868
/proc/meminfo: memFree=189644/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=50840 CPUtime=20.3
/proc/21857/stat : 21857 (packup) S 21856 21856 1511 34817 1511 4202496 12666 146031 0 0 209 84 1625 112 18 0 1 0 4625934 52060160 11970 1283457024 134512640 134752139 4294463824 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/21857/statm: 12710 11970 333 59 0 11874 0
[pid=21867] ppid=21857 vsize=1668 CPUtime=0
/proc/21867/stat : 21867 (sh) S 21857 21856 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4627980 1708032 123 1283457024 134512640 134593992 4293919136 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/21867/statm: 417 123 108 20 0 44 0
[pid=21868] ppid=21867 vsize=137728 CPUtime=5.04
/proc/21868/stat : 21868 (minisatp_32) R 21867 21856 1511 34817 1511 4202496 47707 0 0 0 469 35 0 0 25 0 1 0 4627980 141033472 30943 1283457024 134512640 135413687 4288173120 18446744073709551615 134656402 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/21868/statm: 34432 30943 94 220 0 34210 0
Current children cumulated CPU time (s) 25.34
Current children cumulated vsize (KiB) 192808

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

[startup+25.6113 s]
/proc/loadavg: 1.20 1.26 1.12 2/39 21868
/proc/meminfo: memFree=189644/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=50840 CPUtime=20.3
/proc/21857/stat : 21857 (packup) S 21856 21856 1511 34817 1511 4202496 12666 146031 0 0 209 84 1625 112 18 0 1 0 4625934 52060160 11970 1283457024 134512640 134752139 4294463824 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/21857/statm: 12710 11970 333 59 0 11874 0
[pid=21867] ppid=21857 vsize=1668 CPUtime=0
/proc/21867/stat : 21867 (sh) S 21857 21856 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4627980 1708032 123 1283457024 134512640 134593992 4293919136 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/21867/statm: 417 123 108 20 0 44 0
[pid=21868] ppid=21867 vsize=139380 CPUtime=5.14
/proc/21868/stat : 21868 (minisatp_32) R 21867 21856 1511 34817 1511 4202496 47855 0 0 0 479 35 0 0 25 0 1 0 4627980 142725120 31080 1283457024 134512640 135413687 4288173120 18446744073709551615 134688068 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/21868/statm: 34845 31080 94 220 0 34623 0
Current children cumulated CPU time (s) 25.44
Current children cumulated vsize (KiB) 194460

[startup+26.4116 s]
/proc/loadavg: 1.20 1.26 1.12 2/39 21868
/proc/meminfo: memFree=173772/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=50840 CPUtime=20.3
/proc/21857/stat : 21857 (packup) S 21856 21856 1511 34817 1511 4202496 12666 146031 0 0 209 84 1625 112 18 0 1 0 4625934 52060160 11970 1283457024 134512640 134752139 4294463824 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/21857/statm: 12710 11970 333 59 0 11874 0
[pid=21867] ppid=21857 vsize=1668 CPUtime=0
/proc/21867/stat : 21867 (sh) S 21857 21856 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4627980 1708032 123 1283457024 134512640 134593992 4293919136 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/21867/statm: 417 123 108 20 0 44 0
[pid=21868] ppid=21867 vsize=162228 CPUtime=5.94
/proc/21868/stat : 21868 (minisatp_32) R 21867 21856 1511 34817 1511 4202496 54108 0 0 0 554 40 0 0 25 0 1 0 4627980 166121472 35190 1283457024 134512640 135413687 4288173120 18446744073709551615 134668041 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/21868/statm: 40557 35190 107 220 0 40335 0
Current children cumulated CPU time (s) 26.24
Current children cumulated vsize (KiB) 217308

[startup+27.2118 s]
/proc/loadavg: 1.20 1.26 1.12 2/39 21868
/proc/meminfo: memFree=173772/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=50840 CPUtime=20.3
/proc/21857/stat : 21857 (packup) S 21856 21856 1511 34817 1511 4202496 12666 146031 0 0 209 84 1625 112 18 0 1 0 4625934 52060160 11970 1283457024 134512640 134752139 4294463824 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/21857/statm: 12710 11970 333 59 0 11874 0
[pid=21867] ppid=21857 vsize=1668 CPUtime=0
/proc/21867/stat : 21867 (sh) S 21857 21856 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4627980 1708032 123 1283457024 134512640 134593992 4293919136 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/21867/statm: 417 123 108 20 0 44 0
[pid=21868] ppid=21867 vsize=170816 CPUtime=6.74
/proc/21868/stat : 21868 (minisatp_32) R 21867 21856 1511 34817 1511 4202496 57793 0 0 0 631 43 0 0 25 0 1 0 4627980 174915584 36945 1283457024 134512640 135413687 4288173120 18446744073709551615 134650290 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/21868/statm: 42704 36945 108 220 0 42482 0
Current children cumulated CPU time (s) 27.04
Current children cumulated vsize (KiB) 225896

[startup+27.6119 s]
/proc/loadavg: 1.20 1.26 1.12 2/36 21868
/proc/meminfo: memFree=317024/1048576 swapFree=0/0
[pid=21856] ppid=21855 vsize=2572 CPUtime=0
/proc/21856/stat : 21856 (packup2mp4tr-0.) S 21855 21856 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4625934 2633728 274 1283457024 134512640 135304128 4294590880 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/21856/statm: 643 274 233 194 0 30 0
[pid=21857] ppid=21856 vsize=49872 CPUtime=27.44
/proc/21857/stat : 21857 (packup) R 21856 21856 1511 34817 1511 4202496 22482 204073 0 0 220 86 2281 157 18 0 1 0 4625934 51068928 11740 1283457024 134512640 134752139 4294463824 18446744073709551615 134536317 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/21857/statm: 12468 11740 345 59 0 11632 0
Current children cumulated CPU time (s) 27.44
Current children cumulated vsize (KiB) 52444

Child status: 0
Real time (s): 27.6499
CPU time (s): 27.4857
CPU user time (s): 25.0456
CPU system time (s): 2.44015
CPU usage (%): 99.4064
Max. virtual memory (cumulated for all children) (KiB): 271060

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 25.0456
system time used= 2.44015
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 228001
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= 22
involuntary context switches= 418

runsolver used 0 second user time and 0.008 second system time

The end