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/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf.dudf-real.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-real//ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/ff4a1d84-d490-11df-9e6c-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.60 1.48 1.38 3/34 31625
/proc/meminfo: memFree=280864/1048576 swapFree=0/0
[pid=31624] ppid=31623 vsize=2576 CPUtime=0
/proc/31624/stat : 31624 (packup2mp4pa-0.) S 31623 31624 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11275795 2637824 275 1283457024 134512640 135304128 4292954128 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/31624/statm: 644 275 233 194 0 31 0
[pid=31625] ppid=31624 vsize=3848 CPUtime=0
/proc/31625/stat : 31625 (packup) R 31624 31624 4778 34817 4778 4202496 453 0 0 0 0 0 0 0 25 0 1 0 11275795 3940352 382 1283457024 134512640 134752139 4291915488 18446744073709551615 134640361 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/31625/statm: 962 382 286 59 0 126 0

[startup+0.178729 s]
/proc/loadavg: 1.60 1.48 1.38 3/34 31625
/proc/meminfo: memFree=280864/1048576 swapFree=0/0
[pid=31624] ppid=31623 vsize=2576 CPUtime=0
/proc/31624/stat : 31624 (packup2mp4pa-0.) S 31623 31624 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11275795 2637824 275 1283457024 134512640 135304128 4292954128 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/31624/statm: 644 275 233 194 0 31 0
[pid=31625] ppid=31624 vsize=9736 CPUtime=0.17
/proc/31625/stat : 31625 (packup) R 31624 31624 4778 34817 4778 4202496 1924 0 0 0 15 2 0 0 25 0 1 0 11275795 9969664 1853 1283457024 134512640 134752139 4291915488 18446744073709551615 4157597024 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/31625/statm: 2434 1853 286 59 0 1598 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 12312

[startup+0.208737 s]
/proc/loadavg: 1.60 1.48 1.38 3/34 31625
/proc/meminfo: memFree=280864/1048576 swapFree=0/0
[pid=31624] ppid=31623 vsize=2576 CPUtime=0
/proc/31624/stat : 31624 (packup2mp4pa-0.) S 31623 31624 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11275795 2637824 275 1283457024 134512640 135304128 4292954128 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/31624/statm: 644 275 233 194 0 31 0
[pid=31625] ppid=31624 vsize=10660 CPUtime=0.2
/proc/31625/stat : 31625 (packup) R 31624 31624 4778 34817 4778 4202496 2139 0 0 0 18 2 0 0 25 0 1 0 11275795 10915840 2068 1283457024 134512640 134752139 4291915488 18446744073709551615 134681697 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/31625/statm: 2665 2068 286 59 0 1829 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13236

[startup+0.308765 s]
/proc/loadavg: 1.60 1.48 1.38 3/34 31625
/proc/meminfo: memFree=280864/1048576 swapFree=0/0
[pid=31624] ppid=31623 vsize=2576 CPUtime=0
/proc/31624/stat : 31624 (packup2mp4pa-0.) S 31623 31624 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11275795 2637824 275 1283457024 134512640 135304128 4292954128 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/31624/statm: 644 275 233 194 0 31 0
[pid=31625] ppid=31624 vsize=13364 CPUtime=0.29
/proc/31625/stat : 31625 (packup) R 31624 31624 4778 34817 4778 4202496 2820 0 0 0 27 2 0 0 25 0 1 0 11275795 13684736 2749 1283457024 134512640 134752139 4291915488 18446744073709551615 134706174 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/31625/statm: 3341 2749 286 59 0 2505 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 15940

[startup+0.708854 s]
/proc/loadavg: 1.60 1.48 1.38 3/34 31625
/proc/meminfo: memFree=280864/1048576 swapFree=0/0
[pid=31624] ppid=31623 vsize=2576 CPUtime=0
/proc/31624/stat : 31624 (packup2mp4pa-0.) S 31623 31624 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11275795 2637824 275 1283457024 134512640 135304128 4292954128 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/31624/statm: 644 275 233 194 0 31 0
[pid=31625] ppid=31624 vsize=23344 CPUtime=0.69
/proc/31625/stat : 31625 (packup) R 31624 31624 4778 34817 4778 4202496 5310 0 0 0 64 5 0 0 25 0 1 0 11275795 23904256 5239 1283457024 134512640 134752139 4291915488 18446744073709551615 4157591098 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/31625/statm: 5836 5239 286 59 0 5000 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 25920

[startup+1.50903 s]
/proc/loadavg: 1.60 1.48 1.38 2/35 31626
/proc/meminfo: memFree=249500/1048576 swapFree=0/0
[pid=31624] ppid=31623 vsize=2576 CPUtime=0
/proc/31624/stat : 31624 (packup2mp4pa-0.) S 31623 31624 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11275795 2637824 275 1283457024 134512640 135304128 4292954128 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/31624/statm: 644 275 233 194 0 31 0
[pid=31625] ppid=31624 vsize=44904 CPUtime=1.49
/proc/31625/stat : 31625 (packup) R 31624 31624 4778 34817 4778 4202496 10842 0 0 0 127 22 0 0 25 0 1 0 11275795 45981696 10490 1283457024 134512640 134752139 4291915488 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/31625/statm: 11226 10490 321 59 0 10390 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 47480

[startup+3.10924 s]
/proc/loadavg: 1.60 1.48 1.38 2/37 31628
/proc/meminfo: memFree=223676/1048576 swapFree=0/0
[pid=31624] ppid=31623 vsize=2576 CPUtime=0
/proc/31624/stat : 31624 (packup2mp4pa-0.) S 31623 31624 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11275795 2637824 275 1283457024 134512640 135304128 4292954128 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/31624/statm: 644 275 233 194 0 31 0
[pid=31625] ppid=31624 vsize=44904 CPUtime=1.52
/proc/31625/stat : 31625 (packup) S 31624 31624 4778 34817 4778 4202496 10846 0 0 0 127 25 0 0 25 0 1 0 11275795 45981696 10493 1283457024 134512640 134752139 4291915488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/31625/statm: 11226 10493 324 59 0 10390 0
[pid=31627] ppid=31625 vsize=1676 CPUtime=0.01
/proc/31627/stat : 31627 (sh) S 31625 31624 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 25 0 1 0 11275949 1716224 124 1283457024 134512640 134593992 4293720432 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31627/statm: 419 124 108 20 0 46 0
[pid=31628] ppid=31627 vsize=56940 CPUtime=1.55
/proc/31628/stat : 31628 (minisatp_32) R 31627 31624 4778 34817 4778 4202496 16452 0 0 0 132 23 0 0 25 0 1 0 11275950 58306560 12273 1283457024 134512640 135413687 4289029392 18446744073709551615 134533295 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/31628/statm: 14235 12273 107 220 0 14013 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 106096

[startup+6.31055 s]
/proc/loadavg: 1.55 1.47 1.38 2/37 31630
/proc/meminfo: memFree=220584/1048576 swapFree=0/0
[pid=31624] ppid=31623 vsize=2576 CPUtime=0
/proc/31624/stat : 31624 (packup2mp4pa-0.) S 31623 31624 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11275795 2637824 275 1283457024 134512640 135304128 4292954128 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/31624/statm: 644 275 233 194 0 31 0
[pid=31625] ppid=31624 vsize=44908 CPUtime=4.68
/proc/31625/stat : 31625 (packup) S 31624 31624 4778 34817 4778 4202496 10924 27053 0 0 142 38 258 30 18 0 1 0 11275795 45985792 10502 1283457024 134512640 134752139 4291915488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/31625/statm: 11227 10502 332 59 0 10391 0
[pid=31629] ppid=31625 vsize=1668 CPUtime=0
/proc/31629/stat : 31629 (sh) S 31625 31624 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11276266 1708032 123 1283457024 134512640 134593992 4294261248 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31629/statm: 417 123 108 20 0 44 0
[pid=31630] ppid=31629 vsize=73596 CPUtime=1.6
/proc/31630/stat : 31630 (minisatp_32) R 31629 31624 4778 34817 4778 4202496 19822 0 0 0 148 12 0 0 25 0 1 0 11276266 75362304 15715 1283457024 134512640 135413687 4292329536 18446744073709551615 134686248 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/31630/statm: 18399 15715 108 220 0 18177 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 122748

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

[startup+6.41059 s]
/proc/loadavg: 1.55 1.47 1.38 2/37 31630
/proc/meminfo: memFree=220584/1048576 swapFree=0/0
[pid=31624] ppid=31623 vsize=2576 CPUtime=0
/proc/31624/stat : 31624 (packup2mp4pa-0.) S 31623 31624 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11275795 2637824 275 1283457024 134512640 135304128 4292954128 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/31624/statm: 644 275 233 194 0 31 0
[pid=31625] ppid=31624 vsize=44908 CPUtime=4.68
/proc/31625/stat : 31625 (packup) S 31624 31624 4778 34817 4778 4202496 10924 27053 0 0 142 38 258 30 18 0 1 0 11275795 45985792 10502 1283457024 134512640 134752139 4291915488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/31625/statm: 11227 10502 332 59 0 10391 0
[pid=31629] ppid=31625 vsize=1668 CPUtime=0
/proc/31629/stat : 31629 (sh) S 31625 31624 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11276266 1708032 123 1283457024 134512640 134593992 4294261248 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31629/statm: 417 123 108 20 0 44 0
[pid=31630] ppid=31629 vsize=82632 CPUtime=1.7
/proc/31630/stat : 31630 (minisatp_32) R 31629 31624 4778 34817 4778 4202496 23232 0 0 0 158 12 0 0 25 0 1 0 11276266 84615168 18723 1283457024 134512640 135413687 4292329536 18446744073709551615 134648935 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/31630/statm: 20658 18723 108 220 0 20436 0
Current children cumulated CPU time (s) 6.38
Current children cumulated vsize (KiB) 131784

[startup+7.21079 s]
/proc/loadavg: 1.55 1.47 1.38 2/37 31630
/proc/meminfo: memFree=155360/1048576 swapFree=0/0
[pid=31624] ppid=31623 vsize=2576 CPUtime=0
/proc/31624/stat : 31624 (packup2mp4pa-0.) S 31623 31624 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11275795 2637824 275 1283457024 134512640 135304128 4292954128 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/31624/statm: 644 275 233 194 0 31 0
[pid=31625] ppid=31624 vsize=44908 CPUtime=4.68
/proc/31625/stat : 31625 (packup) S 31624 31624 4778 34817 4778 4202496 10924 27053 0 0 142 38 258 30 18 0 1 0 11275795 45985792 10502 1283457024 134512640 134752139 4291915488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/31625/statm: 11227 10502 332 59 0 10391 0
[pid=31629] ppid=31625 vsize=1668 CPUtime=0
/proc/31629/stat : 31629 (sh) S 31625 31624 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11276266 1708032 123 1283457024 134512640 134593992 4294261248 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31629/statm: 417 123 108 20 0 44 0
[pid=31630] ppid=31629 vsize=119824 CPUtime=2.49
/proc/31630/stat : 31630 (minisatp_32) R 31629 31624 4778 34817 4778 4202496 31333 0 0 0 231 18 0 0 25 0 1 0 11276266 122699776 26103 1283457024 134512640 135413687 4292329536 18446744073709551615 134683835 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/31630/statm: 29956 26103 108 220 0 29734 0
Current children cumulated CPU time (s) 7.17
Current children cumulated vsize (KiB) 168976

[startup+8.01104 s]
/proc/loadavg: 1.55 1.47 1.38 2/37 31630
/proc/meminfo: memFree=138496/1048576 swapFree=0/0
[pid=31624] ppid=31623 vsize=2576 CPUtime=0
/proc/31624/stat : 31624 (packup2mp4pa-0.) S 31623 31624 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11275795 2637824 275 1283457024 134512640 135304128 4292954128 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/31624/statm: 644 275 233 194 0 31 0
[pid=31625] ppid=31624 vsize=44908 CPUtime=4.68
/proc/31625/stat : 31625 (packup) S 31624 31624 4778 34817 4778 4202496 10924 27053 0 0 142 38 258 30 18 0 1 0 11275795 45985792 10502 1283457024 134512640 134752139 4291915488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/31625/statm: 11227 10502 332 59 0 10391 0
[pid=31629] ppid=31625 vsize=1668 CPUtime=0
/proc/31629/stat : 31629 (sh) S 31625 31624 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11276266 1708032 123 1283457024 134512640 134593992 4294261248 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31629/statm: 417 123 108 20 0 44 0
[pid=31630] ppid=31629 vsize=110296 CPUtime=3.3
/proc/31630/stat : 31630 (minisatp_32) R 31629 31624 4778 34817 4778 4202496 33570 0 0 0 310 20 0 0 25 0 1 0 11276266 112943104 25145 1283457024 134512640 135413687 4292329536 18446744073709551615 134698760 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/31630/statm: 27574 25145 108 220 0 27352 0
Current children cumulated CPU time (s) 7.98
Current children cumulated vsize (KiB) 159448

[startup+8.41116 s]
/proc/loadavg: 1.55 1.47 1.38 2/37 31630
/proc/meminfo: memFree=138496/1048576 swapFree=0/0
[pid=31624] ppid=31623 vsize=2576 CPUtime=0
/proc/31624/stat : 31624 (packup2mp4pa-0.) S 31623 31624 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11275795 2637824 275 1283457024 134512640 135304128 4292954128 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/31624/statm: 644 275 233 194 0 31 0
[pid=31625] ppid=31624 vsize=44908 CPUtime=4.68
/proc/31625/stat : 31625 (packup) S 31624 31624 4778 34817 4778 4202496 10924 27053 0 0 142 38 258 30 18 0 1 0 11275795 45985792 10502 1283457024 134512640 134752139 4291915488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/31625/statm: 11227 10502 332 59 0 10391 0
[pid=31629] ppid=31625 vsize=1668 CPUtime=0
/proc/31629/stat : 31629 (sh) S 31625 31624 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11276266 1708032 123 1283457024 134512640 134593992 4294261248 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31629/statm: 417 123 108 20 0 44 0
[pid=31630] ppid=31629 vsize=101888 CPUtime=3.7
/proc/31630/stat : 31630 (minisatp_32) R 31629 31624 4778 34817 4778 4202496 35476 0 0 0 350 20 0 0 25 0 1 0 11276266 104333312 23660 1283457024 134512640 135413687 4292329536 18446744073709551615 134597339 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/31630/statm: 25472 23660 117 220 0 25250 0
Current children cumulated CPU time (s) 8.38
Current children cumulated vsize (KiB) 151040

[startup+8.51118 s]
/proc/loadavg: 1.55 1.47 1.38 2/37 31630
/proc/meminfo: memFree=138496/1048576 swapFree=0/0
[pid=31624] ppid=31623 vsize=2576 CPUtime=0
/proc/31624/stat : 31624 (packup2mp4pa-0.) S 31623 31624 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11275795 2637824 275 1283457024 134512640 135304128 4292954128 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/31624/statm: 644 275 233 194 0 31 0
[pid=31625] ppid=31624 vsize=44136 CPUtime=8.48
/proc/31625/stat : 31625 (packup) R 31624 31624 4778 34817 4778 4202496 16115 62677 0 0 144 44 610 50 18 0 1 0 11275795 45195264 10322 1283457024 134512640 134752139 4291915488 18446744073709551615 4159361220 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/31625/statm: 11034 10322 345 59 0 10198 0
Current children cumulated CPU time (s) 8.48
Current children cumulated vsize (KiB) 46712

Child status: 0
Real time (s): 8.58518
CPU time (s): 8.56053
CPU user time (s): 7.60448
CPU system time (s): 0.956059
CPU usage (%): 99.713
Max. virtual memory (cumulated for all children) (KiB): 168976

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

runsolver used 0 second user time and 0.004 second system time

The end