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/8afdd89e-51b8-11e0-acd7-00163e1e087d.cudf.dudf-real.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-real//8afdd89e-51b8-11e0-acd7-00163e1e087d.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/8afdd89e-51b8-11e0-acd7-00163e1e087d.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.68 1.48 1.32 4/35 26156
/proc/meminfo: memFree=266096/1048576 swapFree=0/0
[pid=26155] ppid=26154 vsize=2576 CPUtime=0
/proc/26155/stat : 26155 (packup2mp4pa-0.) S 26154 26155 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11209585 2637824 275 1283457024 134512640 135304128 4290254208 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26155/statm: 644 275 233 194 0 31 0
[pid=26156] ppid=26155 vsize=3712 CPUtime=0
/proc/26156/stat : 26156 (packup) R 26155 26155 4778 34817 4778 4202496 409 0 0 0 0 0 0 0 25 0 1 0 11209585 3801088 337 1283457024 134512640 134752139 4293367872 18446744073709551615 4159218014 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26156/statm: 928 337 286 59 0 92 0

[startup+0.173985 s]
/proc/loadavg: 1.68 1.48 1.32 4/35 26156
/proc/meminfo: memFree=266096/1048576 swapFree=0/0
[pid=26155] ppid=26154 vsize=2576 CPUtime=0
/proc/26155/stat : 26155 (packup2mp4pa-0.) S 26154 26155 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11209585 2637824 275 1283457024 134512640 135304128 4290254208 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26155/statm: 644 275 233 194 0 31 0
[pid=26156] ppid=26155 vsize=9464 CPUtime=0.18
/proc/26156/stat : 26156 (packup) R 26155 26155 4778 34817 4778 4202496 1861 0 0 0 18 0 0 0 25 0 1 0 11209585 9691136 1789 1283457024 134512640 134752139 4293367872 18446744073709551615 134681665 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26156/statm: 2366 1789 286 59 0 1530 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 12040

[startup+0.203984 s]
/proc/loadavg: 1.68 1.48 1.32 4/35 26156
/proc/meminfo: memFree=266096/1048576 swapFree=0/0
[pid=26155] ppid=26154 vsize=2576 CPUtime=0
/proc/26155/stat : 26155 (packup2mp4pa-0.) S 26154 26155 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11209585 2637824 275 1283457024 134512640 135304128 4290254208 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26155/statm: 644 275 233 194 0 31 0
[pid=26156] ppid=26155 vsize=10256 CPUtime=0.2
/proc/26156/stat : 26156 (packup) R 26155 26155 4778 34817 4778 4202496 2071 0 0 0 20 0 0 0 25 0 1 0 11209585 10502144 1999 1283457024 134512640 134752139 4293367872 18446744073709551615 134681839 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26156/statm: 2564 1999 286 59 0 1728 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12832

[startup+0.314011 s]
/proc/loadavg: 1.68 1.48 1.32 4/35 26156
/proc/meminfo: memFree=266096/1048576 swapFree=0/0
[pid=26155] ppid=26154 vsize=2576 CPUtime=0
/proc/26155/stat : 26155 (packup2mp4pa-0.) S 26154 26155 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11209585 2637824 275 1283457024 134512640 135304128 4290254208 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26155/statm: 644 275 233 194 0 31 0
[pid=26156] ppid=26155 vsize=13508 CPUtime=0.32
/proc/26156/stat : 26156 (packup) R 26155 26155 4778 34817 4778 4202496 2860 0 0 0 32 0 0 0 25 0 1 0 11209585 13832192 2788 1283457024 134512640 134752139 4293367872 18446744073709551615 134681669 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26156/statm: 3377 2788 286 59 0 2541 0
Current children cumulated CPU time (s) 0.32
Current children cumulated vsize (KiB) 16084

[startup+0.704095 s]
/proc/loadavg: 1.68 1.48 1.32 4/35 26156
/proc/meminfo: memFree=266096/1048576 swapFree=0/0
[pid=26155] ppid=26154 vsize=2576 CPUtime=0
/proc/26155/stat : 26155 (packup2mp4pa-0.) S 26154 26155 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11209585 2637824 275 1283457024 134512640 135304128 4290254208 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26155/statm: 644 275 233 194 0 31 0
[pid=26156] ppid=26155 vsize=23472 CPUtime=0.7
/proc/26156/stat : 26156 (packup) R 26155 26155 4778 34817 4778 4202496 5356 0 0 0 68 2 0 0 25 0 1 0 11209585 24035328 5284 1283457024 134512640 134752139 4293367872 18446744073709551615 134681685 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26156/statm: 5868 5284 286 59 0 5032 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 26048

[startup+1.5043 s]
/proc/loadavg: 1.68 1.48 1.32 4/38 26159
/proc/meminfo: memFree=234308/1048576 swapFree=0/0
[pid=26155] ppid=26154 vsize=2576 CPUtime=0
/proc/26155/stat : 26155 (packup2mp4pa-0.) S 26154 26155 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11209585 2637824 275 1283457024 134512640 135304128 4290254208 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26155/statm: 644 275 233 194 0 31 0
[pid=26156] ppid=26155 vsize=34304 CPUtime=1.09
/proc/26156/stat : 26156 (packup) S 26155 26155 4778 34817 4778 4202496 8112 0 0 0 97 12 0 0 25 0 1 0 11209585 35127296 7932 1283457024 134512640 134752139 4293367872 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26156/statm: 8576 7932 324 59 0 7740 0
[pid=26158] ppid=26156 vsize=1676 CPUtime=0
/proc/26158/stat : 26158 (sh) S 26156 26155 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 25 0 1 0 11209695 1716224 124 1283457024 134512640 134593992 4288754880 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26158/statm: 419 124 108 20 0 46 0
[pid=26159] ppid=26158 vsize=14364 CPUtime=0.4
/proc/26159/stat : 26159 (minisatp_32) R 26158 26155 4778 34817 4778 4202496 2692 0 0 0 40 0 0 0 25 0 1 0 11209696 14708736 2287 1283457024 134512640 135413687 4293458256 18446744073709551615 134971216 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26159/statm: 3591 2287 77 220 0 3369 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 52920

[startup+3.10472 s]
/proc/loadavg: 1.63 1.47 1.32 2/38 26159
/proc/meminfo: memFree=189420/1048576 swapFree=0/0
[pid=26155] ppid=26154 vsize=2576 CPUtime=0
/proc/26155/stat : 26155 (packup2mp4pa-0.) S 26154 26155 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11209585 2637824 275 1283457024 134512640 135304128 4290254208 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26155/statm: 644 275 233 194 0 31 0
[pid=26156] ppid=26155 vsize=34308 CPUtime=2.98
/proc/26156/stat : 26156 (packup) S 26155 26155 4778 34817 4778 4202496 8174 19030 0 0 105 20 162 11 18 0 1 0 11209585 35131392 7941 1283457024 134512640 134752139 4293367872 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26156/statm: 8577 7941 332 59 0 7741 0
Current children cumulated CPU time (s) 2.98
Current children cumulated vsize (KiB) 36884

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

[startup+3.20475 s]
/proc/loadavg: 1.63 1.47 1.32 2/38 26159
/proc/meminfo: memFree=189420/1048576 swapFree=0/0
[pid=26155] ppid=26154 vsize=2576 CPUtime=0
/proc/26155/stat : 26155 (packup2mp4pa-0.) S 26154 26155 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11209585 2637824 275 1283457024 134512640 135304128 4290254208 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26155/statm: 644 275 233 194 0 31 0
[pid=26156] ppid=26155 vsize=34308 CPUtime=2.98
/proc/26156/stat : 26156 (packup) S 26155 26155 4778 34817 4778 4202496 8174 19030 0 0 105 20 162 11 18 0 1 0 11209585 35131392 7941 1283457024 134512640 134752139 4293367872 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26156/statm: 8577 7941 332 59 0 7741 0
Current children cumulated CPU time (s) 2.98
Current children cumulated vsize (KiB) 36884

[startup+4.00493 s]
/proc/loadavg: 1.63 1.47 1.32 2/38 26161
/proc/meminfo: memFree=227488/1048576 swapFree=0/0
[pid=26155] ppid=26154 vsize=2576 CPUtime=0
/proc/26155/stat : 26155 (packup2mp4pa-0.) S 26154 26155 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11209585 2637824 275 1283457024 134512640 135304128 4290254208 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26155/statm: 644 275 233 194 0 31 0
[pid=26156] ppid=26155 vsize=34308 CPUtime=2.98
/proc/26156/stat : 26156 (packup) S 26155 26155 4778 34817 4778 4202496 8174 19030 0 0 105 20 162 11 18 0 1 0 11209585 35131392 7941 1283457024 134512640 134752139 4293367872 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26156/statm: 8577 7941 332 59 0 7741 0
[pid=26160] ppid=26156 vsize=1668 CPUtime=0
/proc/26160/stat : 26160 (sh) S 26156 26155 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11209886 1708032 123 1283457024 134512640 134593992 4291964864 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26160/statm: 417 123 108 20 0 44 0
[pid=26161] ppid=26160 vsize=51324 CPUtime=1
/proc/26161/stat : 26161 (minisatp_32) R 26160 26155 4778 34817 4778 4202496 15043 0 0 0 90 10 0 0 23 0 1 0 11209886 52555776 11216 1283457024 134512640 135413687 4290240064 18446744073709551615 134686593 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26161/statm: 12831 11216 108 220 0 12609 0
Current children cumulated CPU time (s) 3.98
Current children cumulated vsize (KiB) 89876

[startup+4.80519 s]
/proc/loadavg: 1.63 1.47 1.32 2/38 26161
/proc/meminfo: memFree=173920/1048576 swapFree=0/0
[pid=26155] ppid=26154 vsize=2576 CPUtime=0
/proc/26155/stat : 26155 (packup2mp4pa-0.) S 26154 26155 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11209585 2637824 275 1283457024 134512640 135304128 4290254208 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26155/statm: 644 275 233 194 0 31 0
[pid=26156] ppid=26155 vsize=34308 CPUtime=2.98
/proc/26156/stat : 26156 (packup) S 26155 26155 4778 34817 4778 4202496 8174 19030 0 0 105 20 162 11 18 0 1 0 11209585 35131392 7941 1283457024 134512640 134752139 4293367872 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26156/statm: 8577 7941 332 59 0 7741 0
[pid=26160] ppid=26156 vsize=1668 CPUtime=0
/proc/26160/stat : 26160 (sh) S 26156 26155 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11209886 1708032 123 1283457024 134512640 134593992 4291964864 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26160/statm: 417 123 108 20 0 44 0
[pid=26161] ppid=26160 vsize=68996 CPUtime=1.79
/proc/26161/stat : 26161 (minisatp_32) R 26160 26155 4778 34817 4778 4202496 21783 0 0 0 164 15 0 0 25 0 1 0 11209886 70651904 15314 1283457024 134512640 135413687 4290240064 18446744073709551615 134698799 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26161/statm: 17249 15314 108 220 0 17027 0
Current children cumulated CPU time (s) 4.77
Current children cumulated vsize (KiB) 107548

[startup+5.20532 s]
/proc/loadavg: 1.63 1.47 1.32 2/38 26161
/proc/meminfo: memFree=173920/1048576 swapFree=0/0
[pid=26155] ppid=26154 vsize=2576 CPUtime=0
/proc/26155/stat : 26155 (packup2mp4pa-0.) S 26154 26155 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11209585 2637824 275 1283457024 134512640 135304128 4290254208 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26155/statm: 644 275 233 194 0 31 0
[pid=26156] ppid=26155 vsize=32476 CPUtime=5.19
/proc/26156/stat : 26156 (packup) R 26155 26155 4778 34817 4778 4202496 15456 42106 0 0 114 21 356 28 18 0 1 0 11209585 33255424 7600 1283457024 134512640 134752139 4293367872 18446744073709551615 4157416736 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26156/statm: 8119 7600 345 59 0 7283 0
Current children cumulated CPU time (s) 5.19
Current children cumulated vsize (KiB) 35052

Child status: 0
Real time (s): 5.21058
CPU time (s): 5.19632
CPU user time (s): 4.70429
CPU system time (s): 0.49203
CPU usage (%): 99.7263
Max. virtual memory (cumulated for all children) (KiB): 113524

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

runsolver used 0 second user time and 0 second system time

The end