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: runsolver -s SIGUSR1 -M 1124 -C 300 -d 10 -w /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/difficult/rand425.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand425.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/difficult/rand425.cudf.result -count(removed),-sum(solution,installedsize),-notuptodate(solution),-unsat_recommends(solution),-count(new) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 300 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 330 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

[startup+0 s]
/proc/loadavg: 0.87 0.98 0.97 2/59 17060
/proc/meminfo: memFree=387708/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=3152 CPUtime=0
/proc/17060/stat : 17060 (runsolver) R 17059 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119472974 3227648 32 18446744073709551615 134512640 134586868 4291269488 4291267536 4151649328 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/17060/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.123044 s]
/proc/loadavg: 0.87 0.98 0.97 2/59 17060
/proc/meminfo: memFree=387708/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=0.03
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 739 3610 2 7 0 0 3 0 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343632 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200351 s]
/proc/loadavg: 0.87 0.98 0.97 2/59 17060
/proc/meminfo: memFree=387708/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=0.03
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 739 3610 2 7 0 0 3 0 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343632 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300245 s]
/proc/loadavg: 0.87 0.98 0.97 2/59 17060
/proc/meminfo: memFree=387708/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=0.03
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 739 3610 2 7 0 0 3 0 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343632 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700195 s]
/proc/loadavg: 0.87 0.98 0.97 2/59 17060
/proc/meminfo: memFree=387708/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=0.03
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 739 3610 2 7 0 0 3 0 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343632 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50024 s]
/proc/loadavg: 0.88 0.98 0.97 2/61 17076
/proc/meminfo: memFree=338340/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=0.03
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 739 3610 2 7 0 0 3 0 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343632 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
[pid=17076] ppid=17060 vsize=50676 CPUtime=1.29
/proc/17076/stat : 17076 (cudf2lp) R 17060 17060 1750 0 -1 4202496 14842 0 0 0 126 3 0 0 20 0 1 0 119472986 51892224 11443 18446744073709551615 4194304 5690517 140734679662864 140734679660504 4970688 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/17076/statm: 12669 11443 160 366 0 12300 0
Current children cumulated CPU time (s) 1.32
Current children cumulated vsize (KiB) 59888

[startup+3.10027 s]
/proc/loadavg: 0.88 0.98 0.97 2/61 17076
/proc/meminfo: memFree=278944/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=0.03
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 739 3610 2 7 0 0 3 0 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343632 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
[pid=17076] ppid=17060 vsize=114764 CPUtime=2.87
/proc/17076/stat : 17076 (cudf2lp) R 17060 17060 1750 0 -1 4202496 39320 0 0 0 276 11 0 0 20 0 1 0 119472986 117518336 28363 18446744073709551615 4194304 5690517 140734679662864 140734679659880 4628784 0 0 16781316 0 0 0 0 17 0 0 0 9 0 0
/proc/17076/statm: 28691 28363 174 366 0 28322 0
Current children cumulated CPU time (s) 2.9
Current children cumulated vsize (KiB) 123976

[startup+6.30025 s]
/proc/loadavg: 0.89 0.98 0.97 2/61 17077
/proc/meminfo: memFree=237404/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=3.39
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 764 42932 2 7 0 0 321 18 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343632 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
[pid=17077] ppid=17060 vsize=213788 CPUtime=2.68
/proc/17077/stat : 17077 (gringo) R 17060 17060 1750 0 -1 4202496 53066 0 0 0 252 16 0 0 20 0 1 0 119473333 218918912 44783 18446744073709551615 4194304 6531320 140735540853616 140735540850232 4358998 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17077/statm: 53447 44783 279 571 0 52868 0
Current children cumulated CPU time (s) 6.07
Current children cumulated vsize (KiB) 223000

[startup+12.7003 s]
/proc/loadavg: 0.90 0.98 0.97 2/61 17077
/proc/meminfo: memFree=10112/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=3.39
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 764 42932 2 7 0 0 321 18 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343632 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
[pid=17077] ppid=17060 vsize=771112 CPUtime=8.54
/proc/17077/stat : 17077 (gringo) R 17060 17060 1750 0 -1 4202496 179123 0 0 0 799 55 0 0 20 0 1 0 119473333 789618688 161996 18446744073709551615 4194304 6531320 140735540853616 140735540851288 5502363 0 0 16781316 16386 0 0 0 17 0 0 0 24 0 0
/proc/17077/statm: 192778 161996 283 571 0 192199 0
Current children cumulated CPU time (s) 11.93
Current children cumulated vsize (KiB) 780324

[startup+25.5033 s]
/proc/loadavg: 0.92 0.98 0.97 2/62 17079
/proc/meminfo: memFree=411604/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=12.55
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 801 222059 2 7 0 0 1158 97 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343040 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
[pid=17078] ppid=17060 vsize=234284 CPUtime=11.71
/proc/17078/stat : 17078 (clasp) R 17060 17060 1750 0 -1 4202496 71180 0 23 0 1142 29 0 0 20 0 1 0 119474305 239906816 58087 18446744073709551615 4194304 6238623 140735107301568 140735107298592 4740165 0 0 16781316 18946 0 0 0 17 0 0 0 34 0 0
/proc/17078/statm: 58571 58087 264 500 0 58068 0
[pid=17079] ppid=17060 vsize=22040 CPUtime=0.02
/proc/17079/stat : 17079 (parse.py) S 17060 17060 1750 0 -1 4202496 1303 0 15 0 1 1 0 0 20 0 1 0 119474305 22568960 1128 18446744073709551615 4194304 6642060 140734539695888 140734539694248 139946865821472 0 0 16777220 20994 0 0 0 17 0 0 0 49 0 0
/proc/17079/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 24.28
Current children cumulated vsize (KiB) 265536

[startup+51.1003 s]
/proc/loadavg: 1.00 1.00 0.98 2/62 17079
/proc/meminfo: memFree=411604/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=12.55
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 801 222059 2 7 0 0 1158 97 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343040 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
[pid=17078] ppid=17060 vsize=234284 CPUtime=37.11
/proc/17078/stat : 17078 (clasp) R 17060 17060 1750 0 -1 4202496 71235 0 23 0 3682 29 0 0 20 0 1 0 119474305 239906816 58142 18446744073709551615 4194304 6238623 140735107301568 140735107298592 4332846 0 0 16781316 18946 0 0 0 17 0 0 0 34 0 0
/proc/17078/statm: 58571 58142 264 500 0 58068 0
[pid=17079] ppid=17060 vsize=22040 CPUtime=0.02
/proc/17079/stat : 17079 (parse.py) S 17060 17060 1750 0 -1 4202496 1303 0 15 0 1 1 0 0 20 0 1 0 119474305 22568960 1128 18446744073709551615 4194304 6642060 140734539695888 140734539694248 139946865821472 0 0 16777220 20994 0 0 0 17 0 0 0 49 0 0
/proc/17079/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 49.68
Current children cumulated vsize (KiB) 265536

[startup+102.3 s]
/proc/loadavg: 1.00 1.00 0.98 2/62 17079
/proc/meminfo: memFree=395360/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=12.55
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 801 222059 2 7 0 0 1158 97 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343040 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
[pid=17078] ppid=17060 vsize=249968 CPUtime=87.92
/proc/17078/stat : 17078 (clasp) R 17060 17060 1750 0 -1 4202496 75250 0 23 0 8762 30 0 0 20 0 1 0 119474305 255967232 62157 18446744073709551615 4194304 6238623 140735107301568 140735107298120 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 34 0 0
/proc/17078/statm: 62492 62157 264 500 0 61989 0
[pid=17079] ppid=17060 vsize=22040 CPUtime=0.02
/proc/17079/stat : 17079 (parse.py) S 17060 17060 1750 0 -1 4202496 1303 0 15 0 1 1 0 0 20 0 1 0 119474305 22568960 1128 18446744073709551615 4194304 6642060 140734539695888 140734539694248 139946865821472 0 0 16777220 20994 0 0 0 17 0 0 0 49 0 0
/proc/17079/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 100.49
Current children cumulated vsize (KiB) 281220

[startup+162.3 s]
/proc/loadavg: 1.13 1.03 0.99 2/62 17079
/proc/meminfo: memFree=340924/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=12.55
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 801 222059 2 7 0 0 1158 97 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343040 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
[pid=17078] ppid=17060 vsize=306440 CPUtime=147.47
/proc/17078/stat : 17078 (clasp) R 17060 17060 1750 0 -1 4202496 89198 0 23 0 14711 36 0 0 20 0 1 0 119474305 313794560 76105 18446744073709551615 4194304 6238623 140735107301568 140735107298120 4409910 0 0 16781316 18946 0 0 0 17 0 0 0 34 0 0
/proc/17078/statm: 76610 76105 264 500 0 76107 0
[pid=17079] ppid=17060 vsize=22040 CPUtime=0.02
/proc/17079/stat : 17079 (parse.py) S 17060 17060 1750 0 -1 4202496 1303 0 15 0 1 1 0 0 20 0 1 0 119474305 22568960 1128 18446744073709551615 4194304 6642060 140734539695888 140734539694248 139946865821472 0 0 16777220 20994 0 0 0 17 0 0 0 49 0 0
/proc/17079/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.04
Current children cumulated vsize (KiB) 337692

[startup+222.3 s]
/proc/loadavg: 1.05 1.02 0.99 2/62 17079
/proc/meminfo: memFree=311536/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=12.55
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 801 222059 2 7 0 0 1158 97 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343040 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
[pid=17078] ppid=17060 vsize=334012 CPUtime=207.01
/proc/17078/stat : 17078 (clasp) R 17060 17060 1750 0 -1 4202496 96169 0 23 0 20661 40 0 0 20 0 1 0 119474305 342028288 83076 18446744073709551615 4194304 6238623 140735107301568 140735107298120 4409934 0 0 16781316 18946 0 0 0 17 0 0 0 34 0 0
/proc/17078/statm: 83503 83076 264 500 0 83000 0
[pid=17079] ppid=17060 vsize=22040 CPUtime=0.02
/proc/17079/stat : 17079 (parse.py) S 17060 17060 1750 0 -1 4202496 1303 0 15 0 1 1 0 0 20 0 1 0 119474305 22568960 1128 18446744073709551615 4194304 6642060 140734539695888 140734539694248 139946865821472 0 0 16777220 20994 0 0 0 17 0 0 0 49 0 0
/proc/17079/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 219.58
Current children cumulated vsize (KiB) 365264

[startup+282.3 s]
/proc/loadavg: 1.10 1.03 0.99 2/62 17079
/proc/meminfo: memFree=309924/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=12.55
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 801 222059 2 7 0 0 1158 97 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343040 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
[pid=17078] ppid=17060 vsize=335744 CPUtime=266.57
/proc/17078/stat : 17078 (clasp) R 17060 17060 1750 0 -1 4202496 96598 0 23 0 26615 42 0 0 20 0 1 0 119474305 343801856 83505 18446744073709551615 4194304 6238623 140735107301568 140735107298120 4635573 0 0 16781316 18946 0 0 0 17 0 0 0 34 0 0
/proc/17078/statm: 83936 83505 264 500 0 83433 0
[pid=17079] ppid=17060 vsize=22040 CPUtime=0.02
/proc/17079/stat : 17079 (parse.py) S 17060 17060 1750 0 -1 4202496 1303 0 15 0 1 1 0 0 20 0 1 0 119474305 22568960 1128 18446744073709551615 4194304 6642060 140734539695888 140734539694248 139946865821472 0 0 16777220 20994 0 0 0 17 0 0 0 49 0 0
/proc/17079/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.14
Current children cumulated vsize (KiB) 366996



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+303.4 s]
/proc/loadavg: 1.07 1.03 0.99 2/62 17079
/proc/meminfo: memFree=309676/1022884 swapFree=0/0
[pid=17060] ppid=17059 vsize=9212 CPUtime=12.55
/proc/17060/stat : 17060 (aspcud-full) S 17059 17060 1750 0 -1 4202496 801 222059 2 7 0 0 1158 97 20 0 1 0 119472974 9433088 364 18446744073709551615 4194304 5129932 140734820344976 140734820343040 140293448053854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17060/statm: 2303 364 303 229 0 63 0
[pid=17078] ppid=17060 vsize=335876 CPUtime=287.5
/proc/17078/stat : 17078 (clasp) R 17060 17060 1750 0 -1 4202496 96635 0 23 0 28708 42 0 0 20 0 1 0 119474305 343937024 83542 18446744073709551615 4194304 6238623 140735107301568 140735107298120 4332840 0 0 16781316 18946 0 0 0 17 0 0 0 34 0 0
/proc/17078/statm: 83969 83542 264 500 0 83466 0
[pid=17079] ppid=17060 vsize=22040 CPUtime=0.02
/proc/17079/stat : 17079 (parse.py) S 17060 17060 1750 0 -1 4202496 1303 0 15 0 1 1 0 0 20 0 1 0 119474305 22568960 1128 18446744073709551615 4194304 6642060 140734539695888 140734539694248 139946865821472 0 0 16777220 20994 0 0 0 17 0 0 0 49 0 0
/proc/17079/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 367128

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 303.516
CPU time (s): 300.183
CPU user time (s): 298.727
CPU system time (s): 1.45609
CPU usage (%): 98.9017
Max. virtual memory (cumulated for all children) (KiB): 784424

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.727
system time used= 1.45609
maximum resident set size= 650588
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 321116
page faults= 51
swaps= 0
block input operations= 99272
block output operations= 82032
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 225
involuntary context switches= 34630

runsolver used 0.452028 second user time and 1.21208 second system time

The end