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/201108300820/aspcud-1.5/rand21.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand21.cudf /home/misc2010/tmp/201108300820/aspcud-1.5/rand21.cudf.dudf-random.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.02 1.03 0.93 4/37 2676
/proc/meminfo: memFree=916580/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2584 CPUtime=0
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 372 0 0 0 0 0 0 0 25 0 1 0 51129764 2646016 279 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/2674/statm: 646 279 234 194 0 33 0
[pid=2675] ppid=2674 vsize=2584 CPUtime=0
/proc/2675/stat : 2675 (aspcud-1.5) R 2674 2674 2160 34817 2160 4202560 110 0 0 0 0 0 0 0 25 0 1 0 51129764 2646016 132 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/2675/statm: 646 132 86 194 0 33 0
[pid=2676] ppid=2675 vsize=2584 CPUtime=0
/proc/2676/stat : 2676 (aspcud-1.5) R 2675 2674 2160 34817 2160 4202560 0 0 0 0 0 0 0 0 25 0 1 0 51129764 2646016 46 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/2676/statm: 646 46 0 194 0 33 0

[startup+0.165443 s]
/proc/loadavg: 1.02 1.03 0.93 4/37 2676
/proc/meminfo: memFree=916580/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=0
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 578 1523 0 0 0 0 0 0 25 0 1 0 51129764 2654208 298 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.205463 s]
/proc/loadavg: 1.02 1.03 0.93 4/37 2676
/proc/meminfo: memFree=916580/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=0
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 578 1523 0 0 0 0 0 0 25 0 1 0 51129764 2654208 298 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.305484 s]
/proc/loadavg: 1.02 1.03 0.93 4/37 2676
/proc/meminfo: memFree=916580/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=0
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 578 1523 0 0 0 0 0 0 25 0 1 0 51129764 2654208 298 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.705488 s]
/proc/loadavg: 1.02 1.03 0.93 4/37 2676
/proc/meminfo: memFree=916580/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=0
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 578 1523 0 0 0 0 0 0 25 0 1 0 51129764 2654208 298 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50837 s]
/proc/loadavg: 1.02 1.03 0.93 2/39 2685
/proc/meminfo: memFree=886732/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=0
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 578 1523 0 0 0 0 0 0 25 0 1 0 51129764 2654208 298 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 298 251 194 0 35 0
[pid=2683] ppid=2674 vsize=1928 CPUtime=0
/proc/2683/stat : 2683 (clasp) S 2674 2674 2160 34817 2160 4202496 273 0 19 0 0 0 0 0 23 0 1 0 51129765 1974272 160 1283457024 134512640 136285277 4294154128 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/2683/statm: 482 160 144 433 0 47 0
[pid=2684] ppid=2674 vsize=2584 CPUtime=0
/proc/2684/stat : 2684 (gringo) S 2674 2674 2160 34817 2160 4202496 380 0 23 0 0 0 0 0 22 0 1 0 51129765 2646016 271 1283457024 134512640 136933539 4293390000 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/2684/statm: 646 271 242 592 0 51 0
[pid=2685] ppid=2674 vsize=27488 CPUtime=1.02
/proc/2685/stat : 2685 (cudf2lp) D 2674 2674 2160 34817 2160 4202496 7461 0 15 0 96 6 0 0 25 0 1 0 51129765 28147712 5975 1283457024 134512640 135786343 4294117456 18446744073709551615 135258478 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0
/proc/2685/statm: 6872 5975 128 311 0 6559 0
Current children cumulated CPU time (s) 1.02
Current children cumulated vsize (KiB) 34592

[startup+3.10571 s]
/proc/loadavg: 1.02 1.03 0.93 2/39 2685
/proc/meminfo: memFree=859992/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=0
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 578 1523 0 0 0 0 0 0 25 0 1 0 51129764 2654208 298 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 298 251 194 0 35 0
[pid=2683] ppid=2674 vsize=8088 CPUtime=0.04
/proc/2683/stat : 2683 (clasp) R 2674 2674 2160 34817 2160 4202496 2003 0 22 0 3 1 0 0 18 0 1 0 51129765 8282112 1689 1283457024 134512640 136285277 4294154128 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2683/statm: 2022 1689 177 433 0 1587 0
[pid=2684] ppid=2674 vsize=11996 CPUtime=0.29
/proc/2684/stat : 2684 (gringo) R 2674 2674 2160 34817 2160 4202496 3155 0 23 0 29 0 0 0 18 0 1 0 51129765 12283904 2126 1283457024 134512640 136933539 4293390000 18446744073709551615 136192366 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/2684/statm: 2999 2126 242 592 0 2404 0
[pid=2685] ppid=2674 vsize=43704 CPUtime=2.13
/proc/2685/stat : 2685 (cudf2lp) R 2674 2674 2160 34817 2160 4202496 13488 0 15 0 205 8 0 0 25 0 1 0 51129765 44752896 10732 1283457024 134512640 135786343 4294117456 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/2685/statm: 10926 10732 139 311 0 10613 0
Current children cumulated CPU time (s) 2.46
Current children cumulated vsize (KiB) 66380
heavy processes:

[startup+6.30646 s]
/proc/loadavg: 1.02 1.03 0.93 2/38 2685
/proc/meminfo: memFree=758340/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=0
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 578 1523 0 0 0 0 0 0 25 0 1 0 51129764 2654208 298 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 298 251 194 0 35 0
[pid=2683] ppid=2674 vsize=51072 CPUtime=0.23
/proc/2683/stat : 2683 (clasp) S 2674 2674 2160 34817 2160 4202496 14984 0 22 0 15 8 0 0 18 0 1 0 51129765 52297728 12192 1283457024 134512640 136285277 4294154128 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/2683/statm: 12768 12192 177 433 0 12333 0
[pid=2684] ppid=2674 vsize=72516 CPUtime=2.72
/proc/2684/stat : 2684 (gringo) S 2674 2674 2160 34817 2160 4202496 24512 0 23 0 264 8 0 0 18 0 1 0 51129765 74256384 14505 1283457024 134512640 136933539 4293390000 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/2684/statm: 18129 14505 242 592 0 17534 0
[pid=2685] ppid=2674 vsize=43704 CPUtime=2.69
/proc/2685/stat : 2685 (cudf2lp) R 2674 2674 2160 34817 2160 4202496 13488 0 15 0 260 9 0 0 25 0 1 0 51129765 44752896 10732 1283457024 134512640 135786343 4294117456 18446744073709551615 135208241 0 0 6 0 0 0 0 17 0 0 0 0
/proc/2685/statm: 10926 10732 139 311 0 10613 0
Current children cumulated CPU time (s) 5.64
Current children cumulated vsize (KiB) 169884

[startup+12.7083 s]
/proc/loadavg: 1.10 1.04 0.94 2/37 2685
/proc/meminfo: memFree=656056/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=10.51
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 579 95578 0 38 0 0 1005 46 18 0 1 0 51129764 2654208 298 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 298 251 194 0 35 0
[pid=2683] ppid=2674 vsize=157188 CPUtime=1.54
/proc/2683/stat : 2683 (clasp) R 2674 2674 2160 34817 2160 4202496 46122 0 22 0 133 21 0 0 18 0 1 0 51129765 160960512 38075 1283457024 134512640 136285277 4294154128 18446744073709551615 134780701 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2683/statm: 39297 38075 189 433 0 38862 0
Current children cumulated CPU time (s) 12.05
Current children cumulated vsize (KiB) 159780

[startup+25.5115 s]
/proc/loadavg: 1.07 1.04 0.94 2/36 2685
/proc/meminfo: memFree=612300/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=10.51
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 579 95578 0 38 0 0 1005 46 18 0 1 0 51129764 2654208 298 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 298 251 194 0 35 0
[pid=2683] ppid=2674 vsize=275136 CPUtime=14.33
/proc/2683/stat : 2683 (clasp) R 2674 2674 2160 34817 2160 4202496 82955 0 22 0 1397 36 0 0 25 0 1 0 51129765 281739264 68505 1283457024 134512640 136285277 4294154128 18446744073709551615 134963461 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2683/statm: 68784 68505 234 433 0 68349 0
Current children cumulated CPU time (s) 24.84
Current children cumulated vsize (KiB) 277728

[startup+51.1074 s]
/proc/loadavg: 1.05 1.04 0.94 2/36 2685
/proc/meminfo: memFree=46364/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=10.51
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 579 95578 0 38 0 0 1005 46 18 0 1 0 51129764 2654208 298 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 298 251 194 0 35 0
[pid=2683] ppid=2674 vsize=849044 CPUtime=39.91
/proc/2683/stat : 2683 (clasp) R 2674 2674 2160 34817 2160 4202496 226433 0 22 0 3915 76 0 0 25 0 1 0 51129765 869421056 211983 1283457024 134512640 136285277 4294154128 18446744073709551615 134642088 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2683/statm: 212261 211983 234 433 0 211826 0
Current children cumulated CPU time (s) 50.42
Current children cumulated vsize (KiB) 851636

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

[startup+51.2074 s]
/proc/loadavg: 1.05 1.04 0.94 2/36 2685
/proc/meminfo: memFree=46364/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=10.51
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 579 95578 0 38 0 0 1005 46 18 0 1 0 51129764 2654208 298 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 298 251 194 0 35 0
[pid=2683] ppid=2674 vsize=851184 CPUtime=40.01
/proc/2683/stat : 2683 (clasp) R 2674 2674 2160 34817 2160 4202496 226950 0 22 0 3925 76 0 0 25 0 1 0 51129765 871612416 212500 1283457024 134512640 136285277 4294154128 18446744073709551615 134642084 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2683/statm: 212796 212500 234 433 0 212361 0
Current children cumulated CPU time (s) 50.52
Current children cumulated vsize (KiB) 853776

[startup+54.4081 s]
/proc/loadavg: 1.05 1.04 0.94 2/36 2685
/proc/meminfo: memFree=4340/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=10.51
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 579 95578 0 38 0 0 1005 46 18 0 1 0 51129764 2654208 298 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 298 251 194 0 35 0
[pid=2683] ppid=2674 vsize=936860 CPUtime=43.2
/proc/2683/stat : 2683 (clasp) R 2674 2674 2160 34817 2160 4202496 248385 0 22 0 4234 86 0 0 25 0 1 0 51129765 959344640 233935 1283457024 134512640 136285277 4294154128 18446744073709551615 134965014 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2683/statm: 234215 233935 234 433 0 233780 0
Current children cumulated CPU time (s) 53.71
Current children cumulated vsize (KiB) 939452

[startup+56.0084 s]
/proc/loadavg: 1.12 1.05 0.94 2/36 2685
/proc/meminfo: memFree=4300/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=10.51
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 579 95578 0 38 0 0 1005 46 18 0 1 0 51129764 2654208 298 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 298 251 194 0 35 0
[pid=2683] ppid=2674 vsize=969932 CPUtime=44.79
/proc/2683/stat : 2683 (clasp) R 2674 2674 2160 34817 2160 4202496 256670 0 22 0 4385 94 0 0 25 0 1 0 51129765 993210368 242220 1283457024 134512640 136285277 4294154128 18446744073709551615 134650868 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2683/statm: 242483 242220 234 433 0 242048 0
Current children cumulated CPU time (s) 55.3
Current children cumulated vsize (KiB) 972524

[startup+56.877 s]
/proc/loadavg: 1.12 1.05 0.94 2/36 2685
/proc/meminfo: memFree=4284/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=56.23
/proc/2674/stat : 2674 (aspcud-1.5) D 2673 2674 2160 34817 2160 4202496 589 355780 6 60 0 0 5461 162 18 0 1 0 51129764 2654208 64 1283457024 134512640 135304128 4293324944 18446744073709551615 4160397824 0 65536 4 1132560123 18446744071564252162 0 0 17 0 0 0 0
/proc/2674/statm: 648 64 17 194 0 35 0
Current children cumulated CPU time (s) 56.23
Current children cumulated vsize (KiB) 2592

[startup+57.505 s]
/proc/loadavg: 1.12 1.05 0.94 2/36 2685
/proc/meminfo: memFree=4284/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=56.23
/proc/2674/stat : 2674 (aspcud-1.5) D 2673 2674 2160 34817 2160 4202496 655 355780 14 60 0 0 5461 162 18 0 1 0 51129764 2654208 137 1283457024 134512640 135304128 4293324944 18446744073709551615 135012182 0 0 4 1132560123 18446744071564332000 0 0 17 0 0 0 0
/proc/2674/statm: 648 137 90 194 0 35 0
Current children cumulated CPU time (s) 56.23
Current children cumulated vsize (KiB) 2592

[startup+57.605 s]
/proc/loadavg: 1.12 1.05 0.94 2/36 2685
/proc/meminfo: memFree=4284/1048576 swapFree=0/0
[pid=2674] ppid=2673 vsize=2592 CPUtime=56.23
/proc/2674/stat : 2674 (aspcud-1.5) S 2673 2674 2160 34817 2160 4202496 736 355780 16 60 0 0 5461 162 18 0 1 0 51129764 2654208 203 1283457024 134512640 135304128 4293324944 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/2674/statm: 648 203 156 194 0 35 0
Current children cumulated CPU time (s) 56.23
Current children cumulated vsize (KiB) 2592

Child status: 0
Real time (s): 57.6949
CPU time (s): 56.2435
CPU user time (s): 54.6194
CPU system time (s): 1.6241
CPU usage (%): 97.4844
Max. virtual memory (cumulated for all children) (KiB): 985612

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 54.6194
system time used= 1.6241
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 359135
page faults= 87
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 13313
involuntary context switches= 12208

runsolver used 0 second user time and 0.112007 second system time

The end