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/201108311143/aspuncud-user-1.0/33bb2fbc-9512-11e0-9181-00163e1e087d.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//33bb2fbc-9512-11e0-9181-00163e1e087d.cudf /home/misc2010/tmp/201108311143/aspuncud-user-1.0/33bb2fbc-9512-11e0-9181-00163e1e087d.cudf.dudf-real.result -sum(installedsize) 

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.00 1.00 0.99 5/41 24890
/proc/meminfo: memFree=837888/1048576 swapFree=0/0
[pid=24887] ppid=24886 vsize=2592 CPUtime=0
/proc/24887/stat : 24887 (aspuncud-user-1) S 24886 24887 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 18 0 1 0 63203606 2654208 280 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/24887/statm: 648 280 234 194 0 35 0
[pid=24888] ppid=24887 vsize=2592 CPUtime=0
/proc/24888/stat : 24888 (aspuncud-user-1) S 24887 24887 19908 34817 19908 4202560 118 0 0 0 0 0 0 0 18 0 1 0 63203606 2654208 134 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/24888/statm: 648 134 87 194 0 35 0
[pid=24889] ppid=24888 vsize=2592 CPUtime=0
/proc/24889/stat : 24889 (aspuncud-user-1) R 24888 24887 19908 34817 19908 4202560 127 0 0 0 0 0 0 0 25 0 1 0 63203606 2654208 151 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/24889/statm: 648 151 104 194 0 35 0
[pid=24890] ppid=24889 vsize=2592 CPUtime=0
/proc/24890/stat : 24890 (aspuncud-user-1) R 24889 24887 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 63203606 2654208 47 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/24890/statm: 648 47 0 194 0 35 0

[startup+0.268358 s]
/proc/loadavg: 1.00 1.00 0.99 5/41 24890
/proc/meminfo: memFree=837888/1048576 swapFree=0/0
[pid=24887] ppid=24886 vsize=2596 CPUtime=0
/proc/24887/stat : 24887 (aspuncud-user-1) S 24886 24887 19908 34817 19908 4202496 572 1521 0 0 0 0 0 0 25 0 1 0 63203606 2658304 298 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24887/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.308094 s]
/proc/loadavg: 1.00 1.00 0.99 5/41 24890
/proc/meminfo: memFree=837888/1048576 swapFree=0/0
[pid=24887] ppid=24886 vsize=2596 CPUtime=0
/proc/24887/stat : 24887 (aspuncud-user-1) S 24886 24887 19908 34817 19908 4202496 572 1521 0 0 0 0 0 0 25 0 1 0 63203606 2658304 298 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24887/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.408125 s]
/proc/loadavg: 1.00 1.00 0.99 5/41 24890
/proc/meminfo: memFree=837888/1048576 swapFree=0/0
[pid=24887] ppid=24886 vsize=2596 CPUtime=0
/proc/24887/stat : 24887 (aspuncud-user-1) S 24886 24887 19908 34817 19908 4202496 572 1521 0 0 0 0 0 0 25 0 1 0 63203606 2658304 298 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24887/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.708204 s]
/proc/loadavg: 1.00 1.00 0.99 5/41 24890
/proc/meminfo: memFree=837888/1048576 swapFree=0/0
[pid=24887] ppid=24886 vsize=2596 CPUtime=0
/proc/24887/stat : 24887 (aspuncud-user-1) S 24886 24887 19908 34817 19908 4202496 572 1521 0 0 0 0 0 0 25 0 1 0 63203606 2658304 298 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24887/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.5084 s]
/proc/loadavg: 1.00 1.00 0.99 2/42 24898
/proc/meminfo: memFree=811136/1048576 swapFree=0/0
[pid=24887] ppid=24886 vsize=2596 CPUtime=0
/proc/24887/stat : 24887 (aspuncud-user-1) S 24886 24887 19908 34817 19908 4202496 572 1521 0 0 0 0 0 0 25 0 1 0 63203606 2658304 298 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24887/statm: 649 298 251 194 0 36 0
[pid=24896] ppid=24887 vsize=3444 CPUtime=0
/proc/24896/stat : 24896 (unclasp) S 24887 24887 19908 34817 19908 4202496 408 0 0 0 0 0 0 0 25 0 1 0 63203607 3526656 272 1283457024 134512640 135121179 4290848384 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/24896/statm: 861 272 240 149 0 52 0
[pid=24897] ppid=24887 vsize=2696 CPUtime=0
/proc/24897/stat : 24897 (gringo) S 24887 24887 19908 34817 19908 4202496 386 0 23 0 0 0 0 0 24 0 1 0 63203607 2760704 281 1283457024 134512640 137056543 4292547648 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/24897/statm: 674 281 252 622 0 49 0
[pid=24898] ppid=24887 vsize=34532 CPUtime=1.34
/proc/24898/stat : 24898 (cudf2lp) R 24887 24887 19908 34817 19908 4202496 9697 0 15 0 132 2 0 0 25 0 1 0 63203607 35360768 8118 1283457024 134512640 135786343 4287477104 18446744073709551615 135199273 0 0 6 0 0 0 0 17 0 0 0 0
/proc/24898/statm: 8633 8118 135 311 0 8320 0
Current children cumulated CPU time (s) 1.34
Current children cumulated vsize (KiB) 43268

[startup+3.11155 s]
/proc/loadavg: 1.00 1.00 0.99 3/41 24898
/proc/meminfo: memFree=831496/1048576 swapFree=0/0
[pid=24887] ppid=24886 vsize=2596 CPUtime=1.71
/proc/24887/stat : 24887 (aspuncud-user-1) S 24886 24887 19908 34817 19908 4202496 572 14440 0 38 0 0 165 6 17 0 1 0 63203606 2658304 298 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24887/statm: 649 298 251 194 0 36 0
[pid=24896] ppid=24887 vsize=10976 CPUtime=1.22
/proc/24896/stat : 24896 (unclasp) R 24887 24887 19908 34817 19908 4202496 2572 0 0 0 119 3 0 0 19 0 1 0 63203607 11239424 2208 1283457024 134512640 135121179 4290848384 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24896/statm: 2744 2208 321 149 0 1935 0
Current children cumulated CPU time (s) 2.93
Current children cumulated vsize (KiB) 13572

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

[startup+3.31163 s]
/proc/loadavg: 1.00 1.00 0.99 3/41 24898
/proc/meminfo: memFree=831496/1048576 swapFree=0/0
[pid=24887] ppid=24886 vsize=2596 CPUtime=1.71
/proc/24887/stat : 24887 (aspuncud-user-1) S 24886 24887 19908 34817 19908 4202496 572 14440 0 38 0 0 165 6 17 0 1 0 63203606 2658304 298 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24887/statm: 649 298 251 194 0 36 0
[pid=24896] ppid=24887 vsize=11696 CPUtime=1.42
/proc/24896/stat : 24896 (unclasp) R 24887 24887 19908 34817 19908 4202496 2778 0 0 0 139 3 0 0 19 0 1 0 63203607 11976704 2414 1283457024 134512640 135121179 4290848384 18446744073709551615 134891050 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24896/statm: 2924 2414 321 149 0 2115 0
Current children cumulated CPU time (s) 3.13
Current children cumulated vsize (KiB) 14292

[startup+4.11192 s]
/proc/loadavg: 1.00 1.00 0.99 2/40 24898
/proc/meminfo: memFree=825924/1048576 swapFree=0/0
[pid=24887] ppid=24886 vsize=2596 CPUtime=1.71
/proc/24887/stat : 24887 (aspuncud-user-1) S 24886 24887 19908 34817 19908 4202496 572 14440 0 38 0 0 165 6 17 0 1 0 63203606 2658304 298 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24887/statm: 649 298 251 194 0 36 0
[pid=24896] ppid=24887 vsize=14876 CPUtime=2.23
/proc/24896/stat : 24896 (unclasp) R 24887 24887 19908 34817 19908 4202496 3656 0 0 0 220 3 0 0 21 0 1 0 63203607 15233024 3130 1283457024 134512640 135121179 4290848384 18446744073709551615 134885275 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24896/statm: 3719 3130 323 149 0 2910 0
Current children cumulated CPU time (s) 3.94
Current children cumulated vsize (KiB) 17472

[startup+4.51206 s]
/proc/loadavg: 1.00 1.00 0.99 2/40 24899
/proc/meminfo: memFree=822328/1048576 swapFree=0/0
[pid=24887] ppid=24886 vsize=2596 CPUtime=1.71
/proc/24887/stat : 24887 (aspuncud-user-1) S 24886 24887 19908 34817 19908 4202496 572 14440 0 38 0 0 165 6 17 0 1 0 63203606 2658304 298 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24887/statm: 649 298 251 194 0 36 0
[pid=24896] ppid=24887 vsize=15812 CPUtime=2.63
/proc/24896/stat : 24896 (unclasp) R 24887 24887 19908 34817 19908 4202496 3913 0 0 0 260 3 0 0 22 0 1 0 63203607 16191488 3387 1283457024 134512640 135121179 4290848384 18446744073709551615 134891059 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24896/statm: 3953 3387 323 149 0 3144 0
Current children cumulated CPU time (s) 4.34
Current children cumulated vsize (KiB) 18408

[startup+4.61211 s]
/proc/loadavg: 1.00 1.00 0.99 2/40 24899
/proc/meminfo: memFree=822328/1048576 swapFree=0/0
[pid=24887] ppid=24886 vsize=2596 CPUtime=1.71
/proc/24887/stat : 24887 (aspuncud-user-1) S 24886 24887 19908 34817 19908 4202496 572 14440 0 38 0 0 165 6 17 0 1 0 63203606 2658304 298 1283457024 134512640 135304128 4288398224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24887/statm: 649 298 251 194 0 36 0
[pid=24896] ppid=24887 vsize=16020 CPUtime=2.73
/proc/24896/stat : 24896 (unclasp) R 24887 24887 19908 34817 19908 4202496 3962 0 0 0 270 3 0 0 22 0 1 0 63203607 16404480 3436 1283457024 134512640 135121179 4290848384 18446744073709551615 134891769 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24896/statm: 4005 3436 323 149 0 3196 0
Current children cumulated CPU time (s) 4.44
Current children cumulated vsize (KiB) 18616

Child status: 0
Real time (s): 4.65608
CPU time (s): 4.48828
CPU user time (s): 4.37627
CPU system time (s): 0.112007
CPU usage (%): 96.3962
Max. virtual memory (cumulated for all children) (KiB): 49736

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.37627
system time used= 0.112007
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 21416
page faults= 38
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 180
involuntary context switches= 167

runsolver used 0 second user time and 0.012 second system time

The end