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/install/rand547.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand547.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/install/rand547.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 1.01 1.05 2/60 20990
/proc/meminfo: memFree=637112/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=3152 CPUtime=0
/proc/20990/stat : 20990 (runsolver) R 20989 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 40602727 3227648 32 18446744073709551615 134512640 134586868 4294925760 4294923808 4151792688 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.194666 s]
/proc/loadavg: 0.87 1.01 1.05 2/60 20990
/proc/meminfo: memFree=637112/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=0.03
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 733 3612 0 0 0 0 2 1 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530656 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.20028 s]
/proc/loadavg: 0.87 1.01 1.05 2/60 20990
/proc/meminfo: memFree=637112/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=0.03
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 733 3612 0 0 0 0 2 1 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530656 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300228 s]
/proc/loadavg: 0.87 1.01 1.05 2/60 20990
/proc/meminfo: memFree=637112/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=0.03
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 733 3612 0 0 0 0 2 1 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530656 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700192 s]
/proc/loadavg: 0.87 1.01 1.05 2/60 20990
/proc/meminfo: memFree=637112/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=0.03
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 733 3612 0 0 0 0 2 1 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530656 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50025 s]
/proc/loadavg: 0.87 1.01 1.05 2/62 21006
/proc/meminfo: memFree=578560/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=0.03
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 733 3612 0 0 0 0 2 1 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530656 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
[pid=21006] ppid=20990 vsize=50676 CPUtime=1.44
/proc/21006/stat : 21006 (cudf2lp) R 20990 20990 32685 0 -1 4202496 15156 0 0 0 138 6 0 0 20 0 1 0 40602729 51892224 11758 18446744073709551615 4194304 5690517 140735167661728 140735167659368 4293711 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/21006/statm: 12669 11758 160 366 0 12300 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 59888

[startup+3.10026 s]
/proc/loadavg: 0.87 1.01 1.05 2/62 21006
/proc/meminfo: memFree=525364/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=0.03
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 733 3612 0 0 0 0 2 1 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530656 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
[pid=21006] ppid=20990 vsize=114764 CPUtime=3.04
/proc/21006/stat : 21006 (cudf2lp) R 20990 20990 32685 0 -1 4202496 39318 0 0 0 287 17 0 0 20 0 1 0 40602729 117518336 28362 18446744073709551615 4194304 5690517 140735167661728 140735167658936 4542715 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/21006/statm: 28691 28362 174 366 0 28322 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 123976

[startup+6.30027 s]
/proc/loadavg: 0.88 1.01 1.05 2/62 21007
/proc/meminfo: memFree=472416/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=3.4
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 759 42932 0 0 0 0 318 22 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530656 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
[pid=21007] ppid=20990 vsize=214196 CPUtime=2.84
/proc/21007/stat : 21007 (gringo) R 20990 20990 32685 0 -1 4202496 53298 0 0 0 265 19 0 0 20 0 1 0 40603071 219336704 45016 18446744073709551615 4194304 6531320 140737100466448 140737100463064 4330265 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21007/statm: 53549 45016 279 571 0 52970 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 223408

[startup+12.7003 s]
/proc/loadavg: 0.89 1.01 1.04 2/62 21007
/proc/meminfo: memFree=10004/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=3.4
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 759 42932 0 0 0 0 318 22 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530656 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
[pid=21007] ppid=20990 vsize=739704 CPUtime=9.03
/proc/21007/stat : 21007 (gringo) R 20990 20990 32685 0 -1 4202496 171207 0 0 0 848 55 0 0 20 0 1 0 40603071 757456896 154732 18446744073709551615 4194304 6531320 140737100466448 140737100462376 4601122 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21007/statm: 184926 154732 282 571 0 184347 0
Current children cumulated CPU time (s) 12.43
Current children cumulated vsize (KiB) 748916

[startup+25.5004 s]
/proc/loadavg: 0.92 1.01 1.04 2/63 21009
/proc/meminfo: memFree=424748/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=14.11
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 799 222358 0 0 0 0 1306 105 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530064 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
[pid=21008] ppid=20990 vsize=238116 CPUtime=10.79
/proc/21008/stat : 21008 (clasp) R 20990 20990 32685 0 -1 4202496 71381 0 22 0 1049 30 0 0 20 0 1 0 40604172 243830784 58271 18446744073709551615 4194304 6238623 140736538724752 140736538721776 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 14 0 0
/proc/21008/statm: 59529 58271 264 500 0 59026 0
[pid=21009] ppid=20990 vsize=22040 CPUtime=0.01
/proc/21009/stat : 21009 (parse.py) S 20990 20990 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 40604172 22568960 1128 18446744073709551615 4194304 6642060 140734510979808 140734510978168 140369165649696 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/21009/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 24.91
Current children cumulated vsize (KiB) 269368

[startup+51.1004 s]
/proc/loadavg: 0.94 1.00 1.04 2/63 21009
/proc/meminfo: memFree=421524/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=14.11
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 799 222358 0 0 0 0 1306 105 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530064 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
[pid=21008] ppid=20990 vsize=238116 CPUtime=36.19
/proc/21008/stat : 21008 (clasp) R 20990 20990 32685 0 -1 4202496 72225 0 22 0 3587 32 0 0 20 0 1 0 40604172 243830784 59115 18446744073709551615 4194304 6238623 140736538724752 140736538721776 4677225 0 0 16781316 18946 0 0 0 17 0 0 0 14 0 0
/proc/21008/statm: 59529 59115 264 500 0 59026 0
[pid=21009] ppid=20990 vsize=22040 CPUtime=0.01
/proc/21009/stat : 21009 (parse.py) S 20990 20990 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 40604172 22568960 1128 18446744073709551615 4194304 6642060 140734510979808 140734510978168 140369165649696 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/21009/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.31
Current children cumulated vsize (KiB) 269368

[startup+102.3 s]
/proc/loadavg: 0.97 1.00 1.04 2/63 21009
/proc/meminfo: memFree=421400/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=14.11
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 799 222358 0 0 0 0 1306 105 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530064 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
[pid=21008] ppid=20990 vsize=238116 CPUtime=86.98
/proc/21008/stat : 21008 (clasp) R 20990 20990 32685 0 -1 4202496 72225 0 22 0 8666 32 0 0 20 0 1 0 40604172 243830784 59115 18446744073709551615 4194304 6238623 140736538724752 140736538721776 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 14 0 0
/proc/21008/statm: 59529 59115 264 500 0 59026 0
[pid=21009] ppid=20990 vsize=22040 CPUtime=0.01
/proc/21009/stat : 21009 (parse.py) S 20990 20990 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 40604172 22568960 1128 18446744073709551615 4194304 6642060 140734510979808 140734510978168 140369165649696 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/21009/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.1
Current children cumulated vsize (KiB) 269368

[startup+162.3 s]
/proc/loadavg: 0.99 1.00 1.03 2/63 21009
/proc/meminfo: memFree=326044/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=14.11
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 799 222358 0 0 0 0 1306 105 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530064 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
[pid=21008] ppid=20990 vsize=333136 CPUtime=146.5
/proc/21008/stat : 21008 (clasp) R 20990 20990 32685 0 -1 4202496 96028 0 22 0 14604 46 0 0 20 0 1 0 40604172 341131264 82918 18446744073709551615 4194304 6238623 140736538724752 140736538721776 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 14 0 0
/proc/21008/statm: 83284 82918 264 500 0 82781 0
[pid=21009] ppid=20990 vsize=22040 CPUtime=0.01
/proc/21009/stat : 21009 (parse.py) S 20990 20990 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 40604172 22568960 1128 18446744073709551615 4194304 6642060 140734510979808 140734510978168 140369165649696 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/21009/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.62
Current children cumulated vsize (KiB) 364388

[startup+222.305 s]
/proc/loadavg: 0.99 1.00 1.02 2/63 21009
/proc/meminfo: memFree=318728/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=14.11
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 799 222358 0 0 0 0 1306 105 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530064 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
[pid=21008] ppid=20990 vsize=340488 CPUtime=206.07
/proc/21008/stat : 21008 (clasp) R 20990 20990 32685 0 -1 4202496 97855 0 22 0 20559 48 0 0 20 0 1 0 40604172 348659712 84745 18446744073709551615 4194304 6238623 140736538724752 140736538721776 4332643 0 0 16781316 18946 0 0 0 17 0 0 0 14 0 0
/proc/21008/statm: 85122 84745 264 500 0 84619 0
[pid=21009] ppid=20990 vsize=22040 CPUtime=0.01
/proc/21009/stat : 21009 (parse.py) S 20990 20990 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 40604172 22568960 1128 18446744073709551615 4194304 6642060 140734510979808 140734510978168 140369165649696 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/21009/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.19
Current children cumulated vsize (KiB) 371740

[startup+282.3 s]
/proc/loadavg: 0.99 1.00 1.02 2/63 21009
/proc/meminfo: memFree=313768/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=14.11
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 799 222358 0 0 0 0 1306 105 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530064 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
[pid=21008] ppid=20990 vsize=345544 CPUtime=265.63
/proc/21008/stat : 21008 (clasp) R 20990 20990 32685 0 -1 4202496 99119 0 22 0 26515 48 0 0 20 0 1 0 40604172 353837056 86009 18446744073709551615 4194304 6238623 140736538724752 140736538721304 4686096 0 0 16781316 18946 0 0 0 17 0 0 0 14 0 0
/proc/21008/statm: 86386 86009 264 500 0 85883 0
[pid=21009] ppid=20990 vsize=22040 CPUtime=0.01
/proc/21009/stat : 21009 (parse.py) S 20990 20990 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 40604172 22568960 1128 18446744073709551615 4194304 6642060 140734510979808 140734510978168 140369165649696 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/21009/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.75
Current children cumulated vsize (KiB) 376796



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.8 s]
/proc/loadavg: 0.99 1.00 1.02 2/63 21009
/proc/meminfo: memFree=313644/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=14.11
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 799 222358 0 0 0 0 1306 105 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530064 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
[pid=21008] ppid=20990 vsize=345544 CPUtime=285.97
/proc/21008/stat : 21008 (clasp) R 20990 20990 32685 0 -1 4202496 99119 0 22 0 28549 48 0 0 20 0 1 0 40604172 353837056 86009 18446744073709551615 4194304 6238623 140736538724752 140736538721304 4677225 0 0 16781316 18946 0 0 0 17 0 0 0 14 0 0
/proc/21008/statm: 86386 86009 264 500 0 85883 0
[pid=21009] ppid=20990 vsize=22040 CPUtime=0.01
/proc/21009/stat : 21009 (parse.py) S 20990 20990 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 40604172 22568960 1128 18446744073709551615 4194304 6642060 140734510979808 140734510978168 140369165649696 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/21009/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.09
Current children cumulated vsize (KiB) 376796

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

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

[startup+302.8 s]
/proc/loadavg: 0.99 1.00 1.02 2/63 21009
/proc/meminfo: memFree=313644/1022884 swapFree=0/0
[pid=20990] ppid=20989 vsize=9212 CPUtime=14.11
/proc/20990/stat : 20990 (aspcud-full) S 20989 20990 32685 0 -1 4202496 799 222358 0 0 0 0 1306 105 20 0 1 0 40602727 9433088 364 18446744073709551615 4194304 5129932 140736278532000 140736278530064 140087028667486 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20990/statm: 2303 364 303 229 0 63 0
[pid=21008] ppid=20990 vsize=345544 CPUtime=285.97
/proc/21008/stat : 21008 (clasp) R 20990 20990 32685 0 -1 4202496 99119 0 22 0 28549 48 0 0 20 0 1 0 40604172 353837056 86009 18446744073709551615 4194304 6238623 140736538724752 140736538721304 4677225 0 0 16781316 18946 0 0 0 17 0 0 0 14 0 0
/proc/21008/statm: 86386 86009 264 500 0 85883 0
[pid=21009] ppid=20990 vsize=22040 CPUtime=0.01
/proc/21009/stat : 21009 (parse.py) S 20990 20990 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 40604172 22568960 1128 18446744073709551615 4194304 6642060 140734510979808 140734510978168 140369165649696 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/21009/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.09
Current children cumulated vsize (KiB) 376796

Child status: 0
Real time (s): 302.884
CPU time (s): 300.199
CPU user time (s): 298.599
CPU system time (s): 1.6001
CPU usage (%): 99.1133
Max. virtual memory (cumulated for all children) (KiB): 784280

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.599
system time used= 1.6001
maximum resident set size= 651788
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 323900
page faults= 33
swaps= 0
block input operations= 73184
block output operations= 82256
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 111
involuntary context switches= 4551

runsolver used 0.848053 second user time and 1.42009 second system time

The end