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/rand740.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand740.cudf /home/misc2010/tmp/201108300820/aspcud-1.5/rand740.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.25 1.10 1.03 5/35 10295
/proc/meminfo: memFree=906216/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2588 CPUtime=0
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 372 0 0 0 0 0 0 0 18 0 1 0 55090789 2650112 279 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/10293/statm: 647 279 234 194 0 34 0
[pid=10294] ppid=10293 vsize=2588 CPUtime=0
/proc/10294/stat : 10294 (aspcud-1.5) R 10293 10293 2160 34817 2160 4202560 110 0 0 0 0 0 0 0 25 0 1 0 55090789 2650112 132 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/10294/statm: 647 132 86 194 0 34 0
[pid=10295] ppid=10294 vsize=2588 CPUtime=0
/proc/10295/stat : 10295 (aspcud-1.5) R 10294 10293 2160 34817 2160 4202560 0 0 0 0 0 0 0 0 25 0 1 0 55090789 2650112 46 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/10295/statm: 647 46 0 194 0 34 0

[startup+0.190937 s]
/proc/loadavg: 1.25 1.10 1.03 5/35 10295
/proc/meminfo: memFree=906216/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=0
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 581 1523 0 0 0 0 0 0 25 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.206997 s]
/proc/loadavg: 1.25 1.10 1.03 5/35 10295
/proc/meminfo: memFree=906216/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=0
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 581 1523 0 0 0 0 0 0 25 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.306952 s]
/proc/loadavg: 1.25 1.10 1.03 5/35 10295
/proc/meminfo: memFree=906216/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=0
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 581 1523 0 0 0 0 0 0 25 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.70701 s]
/proc/loadavg: 1.25 1.10 1.03 5/35 10295
/proc/meminfo: memFree=906216/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=0
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 581 1523 0 0 0 0 0 0 25 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50703 s]
/proc/loadavg: 1.25 1.10 1.03 1/37 10304
/proc/meminfo: memFree=889708/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=0
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 581 1523 0 0 0 0 0 0 25 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
[pid=10302] ppid=10293 vsize=1928 CPUtime=0.01
/proc/10302/stat : 10302 (clasp) S 10293 10293 2160 34817 2160 4202496 292 0 0 0 0 1 0 0 25 0 1 0 55090790 1974272 160 1283457024 134512640 136285277 4292310896 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/10302/statm: 482 160 144 433 0 47 0
[pid=10303] ppid=10293 vsize=2584 CPUtime=0
/proc/10303/stat : 10303 (gringo) S 10293 10293 2160 34817 2160 4202496 404 0 0 0 0 0 0 0 25 0 1 0 55090790 2646016 272 1283457024 134512640 136933539 4287785888 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/10303/statm: 646 272 242 592 0 51 0
[pid=10304] ppid=10293 vsize=15676 CPUtime=0.74
/proc/10304/stat : 10304 (cudf2lp) R 10293 10293 2160 34817 2160 4202496 4395 0 0 0 72 2 0 0 22 0 1 0 55090790 16052224 3550 1283457024 134512640 135786343 4290967216 18446744073709551615 134566237 0 0 6 0 0 0 0 17 0 0 0 0
/proc/10304/statm: 3919 3550 128 311 0 3606 0
Current children cumulated CPU time (s) 0.75
Current children cumulated vsize (KiB) 22784

[startup+3.10761 s]
/proc/loadavg: 1.23 1.10 1.03 2/37 10304
/proc/meminfo: memFree=858520/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=0
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 581 1523 0 0 0 0 0 0 25 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
[pid=10302] ppid=10293 vsize=1932 CPUtime=0.01
/proc/10302/stat : 10302 (clasp) S 10293 10293 2160 34817 2160 4202496 349 0 0 0 0 1 0 0 18 0 1 0 55090790 1978368 217 1283457024 134512640 136285277 4292310896 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/10302/statm: 483 217 176 433 0 48 0
[pid=10303] ppid=10293 vsize=2876 CPUtime=0
/proc/10303/stat : 10303 (gringo) R 10293 10293 2160 34817 2160 4202496 458 0 0 0 0 0 0 0 18 0 1 0 55090790 2945024 326 1283457024 134512640 136933539 4287785888 18446744073709551615 134749126 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10303/statm: 719 326 242 592 0 124 0
[pid=10304] ppid=10293 vsize=44568 CPUtime=2.13
/proc/10304/stat : 10304 (cudf2lp) R 10293 10293 2160 34817 2160 4202496 13972 0 0 0 208 5 0 0 25 0 1 0 55090790 45637632 10935 1283457024 134512640 135786343 4290967216 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/10304/statm: 11142 10935 139 311 0 10829 0
Current children cumulated CPU time (s) 2.14
Current children cumulated vsize (KiB) 51972
heavy processes:

[startup+6.30838 s]
/proc/loadavg: 1.23 1.10 1.03 3/37 10304
/proc/meminfo: memFree=760400/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=0
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 581 1523 0 0 0 0 0 0 25 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
[pid=10302] ppid=10293 vsize=46584 CPUtime=0.24
/proc/10302/stat : 10302 (clasp) S 10293 10293 2160 34817 2160 4202496 13746 0 0 0 22 2 0 0 18 0 1 0 55090790 47702016 10932 1283457024 134512640 136285277 4292310896 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/10302/statm: 11646 10932 177 433 0 11211 0
[pid=10303] ppid=10293 vsize=61512 CPUtime=2.51
/proc/10303/stat : 10303 (gringo) S 10293 10293 2160 34817 2160 4202496 21057 0 0 0 242 9 0 0 18 0 1 0 55090790 62988288 13061 1283457024 134512640 136933539 4287785888 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/10303/statm: 15378 13061 242 592 0 14783 0
[pid=10304] ppid=10293 vsize=44568 CPUtime=2.59
/proc/10304/stat : 10304 (cudf2lp) R 10293 10293 2160 34817 2160 4202496 13972 0 0 0 251 8 0 0 25 0 1 0 55090790 45637632 10935 1283457024 134512640 135786343 4290967216 18446744073709551615 134575530 0 0 6 0 0 0 0 17 0 0 0 0
/proc/10304/statm: 11142 10935 139 311 0 10829 0
Current children cumulated CPU time (s) 5.34
Current children cumulated vsize (KiB) 155260

[startup+12.71 s]
/proc/loadavg: 1.27 1.11 1.03 3/38 10306
/proc/meminfo: memFree=525412/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=2.81
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 583 15498 0 0 0 0 273 8 18 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
[pid=10302] ppid=10293 vsize=151724 CPUtime=1.45
/proc/10302/stat : 10302 (clasp) S 10293 10293 2160 34817 2160 4202496 44050 0 0 0 132 13 0 0 18 0 1 0 55090790 155365376 36725 1283457024 134512640 136285277 4292310896 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/10302/statm: 37931 36725 177 433 0 37496 0
[pid=10303] ppid=10293 vsize=87748 CPUtime=7.48
/proc/10303/stat : 10303 (gringo) R 10293 10293 2160 34817 2160 4202496 83498 0 0 0 706 42 0 0 25 0 1 0 55090790 89853952 21497 1283457024 134512640 136933539 4287785888 18446744073709551615 136175597 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10303/statm: 21937 21497 254 592 0 21342 0
Current children cumulated CPU time (s) 11.74
Current children cumulated vsize (KiB) 242068

[startup+25.5136 s]
/proc/loadavg: 1.23 1.11 1.03 2/37 10307
/proc/meminfo: memFree=651288/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=10.42
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 583 98997 0 0 0 0 991 51 18 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
[pid=10302] ppid=10293 vsize=229228 CPUtime=14.09
/proc/10302/stat : 10302 (clasp) R 10293 10293 2160 34817 2160 4202496 72050 0 0 0 1385 24 0 0 25 0 1 0 55090790 234729472 57018 1283457024 134512640 136285277 4292310896 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/10302/statm: 57307 57018 234 433 0 56872 0
Current children cumulated CPU time (s) 24.51
Current children cumulated vsize (KiB) 231824

[startup+51.1099 s]
/proc/loadavg: 1.15 1.10 1.03 2/37 10310
/proc/meminfo: memFree=71712/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=10.42
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 583 98997 0 0 0 0 991 51 18 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
[pid=10302] ppid=10293 vsize=818944 CPUtime=39.66
/proc/10302/stat : 10302 (clasp) R 10293 10293 2160 34817 2160 4202496 219211 0 0 0 3897 69 0 0 25 0 1 0 55090790 838598656 204179 1283457024 134512640 136285277 4292310896 18446744073709551615 134686305 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/10302/statm: 204736 204179 234 433 0 204301 0
Current children cumulated CPU time (s) 50.08
Current children cumulated vsize (KiB) 821540

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

[startup+51.21 s]
/proc/loadavg: 1.15 1.10 1.03 2/37 10310
/proc/meminfo: memFree=71712/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=10.42
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 583 98997 0 0 0 0 991 51 18 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
[pid=10302] ppid=10293 vsize=818944 CPUtime=39.76
/proc/10302/stat : 10302 (clasp) R 10293 10293 2160 34817 2160 4202496 219211 0 0 0 3907 69 0 0 25 0 1 0 55090790 838598656 204179 1283457024 134512640 136285277 4292310896 18446744073709551615 134960246 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/10302/statm: 204736 204179 234 433 0 204301 0
Current children cumulated CPU time (s) 50.18
Current children cumulated vsize (KiB) 821540

[startup+54.4106 s]
/proc/loadavg: 1.14 1.10 1.03 2/37 10310
/proc/meminfo: memFree=4552/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=10.42
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 583 98997 0 0 0 0 991 51 18 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
[pid=10302] ppid=10293 vsize=884656 CPUtime=42.95
/proc/10302/stat : 10302 (clasp) R 10293 10293 2160 34817 2160 4202496 235623 0 0 0 4223 72 0 0 25 0 1 0 55090790 905887744 220591 1283457024 134512640 136285277 4292310896 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/10302/statm: 221164 220591 234 433 0 220729 0
Current children cumulated CPU time (s) 53.37
Current children cumulated vsize (KiB) 887252

[startup+57.6115 s]
/proc/loadavg: 1.21 1.11 1.03 2/37 10310
/proc/meminfo: memFree=4164/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=10.42
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 583 98997 0 0 0 0 991 51 18 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
[pid=10302] ppid=10293 vsize=949660 CPUtime=46.11
/proc/10302/stat : 10302 (clasp) R 10293 10293 2160 34817 2160 4202496 251872 0 0 0 4534 77 0 0 25 0 1 0 55090790 972451840 236840 1283457024 134512640 136285277 4292310896 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/10302/statm: 237415 236840 234 433 0 236980 0
Current children cumulated CPU time (s) 56.53
Current children cumulated vsize (KiB) 952256

[startup+58.4117 s]
/proc/loadavg: 1.21 1.11 1.03 2/37 10311
/proc/meminfo: memFree=4252/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=10.42
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 583 98997 0 0 0 0 991 51 18 0 1 0 55090789 2658304 298 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 298 251 194 0 36 0
[pid=10302] ppid=10293 vsize=968044 CPUtime=46.91
/proc/10302/stat : 10302 (clasp) R 10293 10293 2160 34817 2160 4202496 256481 0 0 0 4609 82 0 0 25 0 1 0 55090790 991277056 241449 1283457024 134512640 136285277 4292310896 18446744073709551615 134649408 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/10302/statm: 242011 241449 234 433 0 241576 0
Current children cumulated CPU time (s) 57.33
Current children cumulated vsize (KiB) 970640

[startup+59.5171 s]
/proc/loadavg: 1.21 1.11 1.03 2/37 10311
/proc/meminfo: memFree=4252/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=58.3
/proc/10293/stat : 10293 (aspcud-1.5) D 10292 10293 2160 34817 2160 4202496 595 359857 7 3 0 0 5673 157 18 0 1 0 55090789 2658304 67 1283457024 134512640 135304128 4289522928 18446744073709551615 4160312735 0 65536 4 1132560123 18446744071564332000 0 0 17 0 0 0 0
/proc/10293/statm: 649 75 28 194 0 36 0
Current children cumulated CPU time (s) 58.3
Current children cumulated vsize (KiB) 2596

[startup+60.0067 s]
/proc/loadavg: 1.21 1.11 1.03 1/37 10312
/proc/meminfo: memFree=984724/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=58.3
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 739 359857 17 3 0 0 5673 157 18 0 1 0 55090789 2658304 203 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 203 156 194 0 36 0
[pid=10312] ppid=10293 vsize=204 CPUtime=0
/proc/10312/stat : 10312 (touch) D 10293 10293 2160 34817 2160 4194304 90 0 4 0 0 0 0 0 19 0 1 0 55096784 208896 33 1283457024 134512640 134554908 4294390256 18446744073709551615 4159888340 0 0 16898 0 18446744071564332000 0 0 17 0 0 0 0
/proc/10312/statm: 51 33 26 11 0 6 0
Current children cumulated CPU time (s) 58.3
Current children cumulated vsize (KiB) 2800

[startup+60.1067 s]
/proc/loadavg: 1.21 1.11 1.03 1/37 10312
/proc/meminfo: memFree=984724/1048576 swapFree=0/0
[pid=10293] ppid=10292 vsize=2596 CPUtime=58.3
/proc/10293/stat : 10293 (aspcud-1.5) S 10292 10293 2160 34817 2160 4202496 792 360061 17 8 0 0 5673 157 19 0 1 0 55090789 2658304 214 1283457024 134512640 135304128 4289522928 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/10293/statm: 649 214 167 194 0 36 0
Current children cumulated CPU time (s) 58.3
Current children cumulated vsize (KiB) 2596

Child status: 0
Real time (s): 60.1719
CPU time (s): 58.3156
CPU user time (s): 56.7395
CPU system time (s): 1.5761
CPU usage (%): 96.9151
Max. virtual memory (cumulated for all children) (KiB): 986840

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 56.7395
system time used= 1.5761
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 363226
page faults= 31
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 13172
involuntary context switches= 12185

runsolver used 0 second user time and 0.056003 second system time

The end