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/rand97.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand97.cudf /home/misc2010/tmp/201108300820/aspcud-1.5/rand97.cudf.user-upgrades.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.01 1.00 3/36 12327
/proc/meminfo: memFree=925436/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2584 CPUtime=0
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 373 0 0 0 0 0 0 0 24 0 1 0 56219507 2646016 279 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/12326/statm: 646 279 234 194 0 33 0
[pid=12327] ppid=12326 vsize=2584 CPUtime=0
/proc/12327/stat : 12327 (aspcud-1.5) R 12326 12326 2160 34817 2160 4202560 42 0 0 0 0 0 0 0 25 0 1 0 56219507 2646016 74 1283457024 134512640 135304128 4293423264 18446744073709551615 135195265 0 0 0 65538 0 0 0 17 0 0 0 0
/proc/12327/statm: 646 74 28 194 0 33 0

[startup+0.192037 s]
/proc/loadavg: 1.00 1.01 1.00 3/36 12327
/proc/meminfo: memFree=925436/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=0.01
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 579 1523 0 0 0 1 0 0 25 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.204056 s]
/proc/loadavg: 1.00 1.01 1.00 3/36 12327
/proc/meminfo: memFree=925436/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=0.01
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 579 1523 0 0 0 1 0 0 25 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.304029 s]
/proc/loadavg: 1.00 1.01 1.00 3/36 12327
/proc/meminfo: memFree=925436/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=0.01
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 579 1523 0 0 0 1 0 0 25 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.704103 s]
/proc/loadavg: 1.00 1.01 1.00 3/36 12327
/proc/meminfo: memFree=925436/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=0.01
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 579 1523 0 0 0 1 0 0 25 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.50409 s]
/proc/loadavg: 1.16 1.05 1.01 2/39 12337
/proc/meminfo: memFree=896888/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=0.01
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 579 1523 0 0 0 1 0 0 25 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
[pid=12335] ppid=12326 vsize=1932 CPUtime=0
/proc/12335/stat : 12335 (clasp) S 12326 12326 2160 34817 2160 4202496 274 0 18 0 0 0 0 0 23 0 1 0 56219508 1978368 160 1283457024 134512640 136285277 4293465840 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/12335/statm: 483 160 144 433 0 48 0
[pid=12336] ppid=12326 vsize=2584 CPUtime=0
/proc/12336/stat : 12336 (gringo) S 12326 12326 2160 34817 2160 4202496 382 0 22 0 0 0 0 0 21 0 1 0 56219508 2646016 272 1283457024 134512640 136933539 4294031040 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/12336/statm: 646 272 242 592 0 51 0
[pid=12337] ppid=12326 vsize=16068 CPUtime=0.73
/proc/12337/stat : 12337 (cudf2lp) R 12326 12326 2160 34817 2160 4202496 4498 0 15 0 71 2 0 0 25 0 1 0 56219508 16453632 3668 1283457024 134512640 135786343 4291300160 18446744073709551615 134566237 0 0 6 0 0 0 0 17 0 0 0 0
/proc/12337/statm: 4017 3668 128 311 0 3704 0
Current children cumulated CPU time (s) 0.74
Current children cumulated vsize (KiB) 23176

[startup+3.11257 s]
/proc/loadavg: 1.16 1.05 1.01 2/39 12337
/proc/meminfo: memFree=872396/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=0.01
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 579 1523 0 0 0 1 0 0 25 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
[pid=12335] ppid=12326 vsize=3200 CPUtime=0
/proc/12335/stat : 12335 (clasp) S 12326 12326 2160 34817 2160 4202496 627 0 21 0 0 0 0 0 18 0 1 0 56219508 3276800 516 1283457024 134512640 136285277 4293465840 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/12335/statm: 800 516 176 433 0 365 0
[pid=12336] ppid=12326 vsize=4692 CPUtime=0.07
/proc/12336/stat : 12336 (gringo) R 12326 12326 2160 34817 2160 4202496 913 0 22 0 7 0 0 0 18 0 1 0 56219508 4804608 705 1283457024 134512640 136933539 4294031040 18446744073709551615 134776899 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12336/statm: 1173 705 242 592 0 578 0
[pid=12337] ppid=12326 vsize=44564 CPUtime=2.1
/proc/12337/stat : 12337 (cudf2lp) R 12326 12326 2160 34817 2160 4202496 13957 0 15 0 204 6 0 0 25 0 1 0 56219508 45633536 10935 1283457024 134512640 135786343 4291300160 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/12337/statm: 11141 10935 139 311 0 10828 0
Current children cumulated CPU time (s) 2.18
Current children cumulated vsize (KiB) 55048
heavy processes:

[startup+6.31329 s]
/proc/loadavg: 1.23 1.06 1.02 3/39 12338
/proc/meminfo: memFree=772460/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=0.01
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 579 1523 0 0 0 1 0 0 25 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
[pid=12335] ppid=12326 vsize=47380 CPUtime=0.26
/proc/12335/stat : 12335 (clasp) S 12326 12326 2160 34817 2160 4202496 13966 0 21 0 16 10 0 0 18 0 1 0 56219508 48517120 11173 1283457024 134512640 136285277 4293465840 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/12335/statm: 11845 11173 177 433 0 11410 0
[pid=12336] ppid=12326 vsize=61908 CPUtime=2.47
/proc/12336/stat : 12336 (gringo) R 12326 12326 2160 34817 2160 4202496 21317 0 22 0 239 8 0 0 18 0 1 0 56219508 63393792 13310 1283457024 134512640 136933539 4294031040 18446744073709551615 134586859 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12336/statm: 15477 13310 242 592 0 14882 0
[pid=12337] ppid=12326 vsize=44564 CPUtime=2.62
/proc/12337/stat : 12337 (cudf2lp) R 12326 12326 2160 34817 2160 4202496 13957 0 15 0 254 8 0 0 25 0 1 0 56219508 45633536 10935 1283457024 134512640 135786343 4291300160 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/12337/statm: 11141 10935 139 311 0 10828 0
Current children cumulated CPU time (s) 5.36
Current children cumulated vsize (KiB) 156444

[startup+12.7049 s]
/proc/loadavg: 1.21 1.06 1.02 2/38 12338
/proc/meminfo: memFree=529568/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=10.26
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 580 98993 0 37 0 1 985 40 18 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
[pid=12335] ppid=12326 vsize=156512 CPUtime=1.5
/proc/12335/stat : 12335 (clasp) R 12326 12326 2160 34817 2160 4202496 45357 0 21 0 121 29 0 0 18 0 1 0 56219508 160268288 37935 1283457024 134512640 136285277 4293465840 18446744073709551615 134783604 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12335/statm: 39128 37935 186 433 0 38693 0
Current children cumulated CPU time (s) 11.76
Current children cumulated vsize (KiB) 159104

[startup+25.5087 s]
/proc/loadavg: 1.16 1.06 1.01 2/37 12340
/proc/meminfo: memFree=698224/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=10.26
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 580 98993 0 37 0 1 985 40 18 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
[pid=12335] ppid=12326 vsize=194144 CPUtime=14.29
/proc/12335/stat : 12335 (clasp) R 12326 12326 2160 34817 2160 4202496 62503 0 21 0 1392 37 0 0 25 0 1 0 56219508 198803456 47999 1283457024 134512640 136285277 4293465840 18446744073709551615 134916024 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12335/statm: 48536 47999 221 433 0 48101 0
Current children cumulated CPU time (s) 24.55
Current children cumulated vsize (KiB) 196736

[startup+51.1075 s]
/proc/loadavg: 1.11 1.05 1.01 2/37 12344
/proc/meminfo: memFree=256448/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=10.26
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 580 98993 0 37 0 1 985 40 18 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
[pid=12335] ppid=12326 vsize=641848 CPUtime=39.86
/proc/12335/stat : 12335 (clasp) R 12326 12326 2160 34817 2160 4202496 175198 0 21 0 3925 61 0 0 25 0 1 0 56219508 657252352 160179 1283457024 134512640 136285277 4293465840 18446744073709551615 134951781 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12335/statm: 160462 160179 234 433 0 160027 0
Current children cumulated CPU time (s) 50.12
Current children cumulated vsize (KiB) 644440

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

[startup+51.2076 s]
/proc/loadavg: 1.11 1.05 1.01 2/37 12344
/proc/meminfo: memFree=256448/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=10.26
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 580 98993 0 37 0 1 985 40 18 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
[pid=12335] ppid=12326 vsize=642024 CPUtime=39.96
/proc/12335/stat : 12335 (clasp) R 12326 12326 2160 34817 2160 4202496 175224 0 21 0 3935 61 0 0 25 0 1 0 56219508 657432576 160205 1283457024 134512640 136285277 4293465840 18446744073709551615 134649003 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12335/statm: 160506 160205 234 433 0 160071 0
Current children cumulated CPU time (s) 50.22
Current children cumulated vsize (KiB) 644616

[startup+57.6088 s]
/proc/loadavg: 1.10 1.05 1.01 2/36 12344
/proc/meminfo: memFree=93900/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=10.26
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 580 98993 0 37 0 1 985 40 18 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
[pid=12335] ppid=12326 vsize=804024 CPUtime=46.36
/proc/12335/stat : 12335 (clasp) R 12326 12326 2160 34817 2160 4202496 215750 0 21 0 4557 79 0 0 25 0 1 0 56219508 823320576 200731 1283457024 134512640 136285277 4293465840 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12335/statm: 201006 200731 234 433 0 200571 0
Current children cumulated CPU time (s) 56.62
Current children cumulated vsize (KiB) 806616

[startup+64.0103 s]
/proc/loadavg: 1.09 1.05 1.01 2/36 12344
/proc/meminfo: memFree=4312/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=10.26
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 580 98993 0 37 0 1 985 40 18 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
[pid=12335] ppid=12326 vsize=939348 CPUtime=52.75
/proc/12335/stat : 12335 (clasp) R 12326 12326 2160 34817 2160 4202496 249550 0 21 0 5180 95 0 0 25 0 1 0 56219508 961892352 234531 1283457024 134512640 136285277 4293465840 18446744073709551615 134669525 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12335/statm: 234837 234531 234 433 0 234402 0
Current children cumulated CPU time (s) 63.01
Current children cumulated vsize (KiB) 941940

[startup+65.6107 s]
/proc/loadavg: 1.09 1.05 1.01 2/36 12344
/proc/meminfo: memFree=4296/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=10.26
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 580 98993 0 37 0 1 985 40 18 0 1 0 56219507 2654208 298 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 298 251 194 0 35 0
[pid=12335] ppid=12326 vsize=971144 CPUtime=54.35
/proc/12335/stat : 12335 (clasp) R 12326 12326 2160 34817 2160 4202496 257499 0 21 0 5336 99 0 0 25 0 1 0 56219508 994451456 242480 1283457024 134512640 136285277 4293465840 18446744073709551615 134733711 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12335/statm: 242786 242480 234 433 0 242351 0
Current children cumulated CPU time (s) 64.61
Current children cumulated vsize (KiB) 973736

[startup+66.4102 s]
/proc/loadavg: 1.16 1.07 1.02 2/36 12344
/proc/meminfo: memFree=4320/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=10.26
/proc/12326/stat : 12326 (aspcud-1.5) S 12325 12326 2160 34817 2160 4202496 580 98993 0 37 0 1 985 40 18 0 1 0 56219507 2654208 287 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12326/statm: 648 287 240 194 0 35 0
[pid=12335] ppid=12326 vsize=980584 CPUtime=55.05
/proc/12335/stat : 12335 (clasp) R 12326 12326 2160 34817 2160 4204544 259848 0 21 0 5402 103 0 0 25 0 1 0 56219508 1004118016 244829 1283457024 134512640 136285277 4293465840 18446744073709551615 134628497 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12335/statm: 245146 244829 234 433 0 244711 0
Current children cumulated CPU time (s) 65.31
Current children cumulated vsize (KiB) 983176

[startup+67.0962 s]
/proc/loadavg: 1.16 1.07 1.02 2/36 12344
/proc/meminfo: memFree=4320/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=65.73
/proc/12326/stat : 12326 (aspcud-1.5) D 12325 12326 2160 34817 2160 4202496 600 359935 8 58 0 1 6409 163 18 0 1 0 56219507 2654208 75 1283457024 134512640 135304128 4293423264 18446744073709551615 4159831056 0 65536 4 1132560123 18446744071564252162 0 0 17 0 0 0 0
/proc/12326/statm: 648 75 28 194 0 35 0
Current children cumulated CPU time (s) 65.73
Current children cumulated vsize (KiB) 2592

[startup+67.2043 s]
/proc/loadavg: 1.16 1.07 1.02 2/36 12344
/proc/meminfo: memFree=4320/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=65.73
/proc/12326/stat : 12326 (aspcud-1.5) R 12325 12326 2160 34817 2160 4202496 720 359935 16 58 0 1 6409 163 18 0 1 0 56219507 2654208 203 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/12326/statm: 648 203 156 194 0 35 0
Current children cumulated CPU time (s) 65.73
Current children cumulated vsize (KiB) 2592

[startup+67.3042 s]
/proc/loadavg: 1.16 1.07 1.02 1/35 12345
/proc/meminfo: memFree=985040/1048576 swapFree=0/0
[pid=12326] ppid=12325 vsize=2592 CPUtime=65.73
/proc/12326/stat : 12326 (aspcud-1.5) R 12325 12326 2160 34817 2160 4202496 751 360138 16 64 0 1 6409 163 18 0 1 0 56219507 2654208 208 1283457024 134512640 135304128 4293423264 18446744073709551615 4294960130 0 0 16902 1132543225 0 0 0 17 0 0 0 0
/proc/12326/statm: 648 208 161 194 0 35 0
Current children cumulated CPU time (s) 65.73
Current children cumulated vsize (KiB) 2592

Child status: 0
Real time (s): 67.371
CPU time (s): 65.7441
CPU user time (s): 64.096
CPU system time (s): 1.6481
CPU usage (%): 97.5852
Max. virtual memory (cumulated for all children) (KiB): 986416

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 64.096
system time used= 1.6481
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 363290
page faults= 86
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 13238
involuntary context switches= 12442

runsolver used 0.004 second user time and 0.072004 second system time

The end