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/rand96.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand96.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/install/rand96.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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.87 0.98 0.99 2/59 369
/proc/meminfo: memFree=550100/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=3152 CPUtime=0
/proc/369/stat : 369 (runsolver) R 368 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 118930494 3227648 33 18446744073709551615 134512640 134586868 4288009568 4288007616 4151964720 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 788 33 0 19 0 73 0

[startup+0.133055 s]
/proc/loadavg: 0.87 0.98 0.99 2/59 369
/proc/meminfo: memFree=550100/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=0.06
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 740 3615 0 5 1 0 3 2 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759712 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.200344 s]
/proc/loadavg: 0.87 0.98 0.99 2/59 369
/proc/meminfo: memFree=550100/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=0.06
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 740 3615 0 5 1 0 3 2 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759712 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300331 s]
/proc/loadavg: 0.87 0.98 0.99 2/59 369
/proc/meminfo: memFree=550100/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=0.06
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 740 3615 0 5 1 0 3 2 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759712 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.700237 s]
/proc/loadavg: 0.87 0.98 0.99 2/59 369
/proc/meminfo: memFree=550100/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=0.06
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 740 3615 0 5 1 0 3 2 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759712 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50034 s]
/proc/loadavg: 0.88 0.98 0.99 2/61 385
/proc/meminfo: memFree=515356/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=0.06
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 740 3615 0 5 1 0 3 2 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759712 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
[pid=385] ppid=369 vsize=51264 CPUtime=1.41
/proc/385/stat : 385 (cudf2lp) R 369 369 1733 0 -1 4202496 11761 0 0 0 135 6 0 0 20 0 1 0 118930501 52494336 10028 18446744073709551615 4194304 5690517 140733202501120 140733202497320 4970635 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/385/statm: 12816 10028 160 366 0 12447 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 60476

[startup+3.10034 s]
/proc/loadavg: 0.88 0.98 0.99 2/61 385
/proc/meminfo: memFree=483364/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=0.06
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 740 3615 0 5 1 0 3 2 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759712 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
[pid=385] ppid=369 vsize=93028 CPUtime=2.99
/proc/385/stat : 385 (cudf2lp) R 369 369 1733 0 -1 4202496 26521 0 0 0 285 14 0 0 20 0 1 0 118930501 95260672 19794 18446744073709551615 4194304 5690517 140733202501120 140733202498760 4960693 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/385/statm: 23257 19794 160 366 0 22888 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 102240

[startup+6.30034 s]
/proc/loadavg: 0.88 0.98 0.99 2/61 386
/proc/meminfo: memFree=494276/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=5.22
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 766 42936 0 5 1 0 489 32 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759712 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
[pid=386] ppid=369 vsize=28720 CPUtime=0.98
/proc/386/stat : 386 (gringo) R 369 369 1733 0 -1 4202496 7554 0 0 0 94 4 0 0 20 0 1 0 118931024 29409280 6443 18446744073709551615 4194304 6531320 140737224128320 140737224124888 5117411 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/386/statm: 7180 6443 259 571 0 6601 0
Current children cumulated CPU time (s) 6.2
Current children cumulated vsize (KiB) 37932

[startup+12.7003 s]
/proc/loadavg: 0.90 0.98 0.99 2/61 386
/proc/meminfo: memFree=208828/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=5.22
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 766 42936 0 5 1 0 489 32 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759712 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
[pid=386] ppid=369 vsize=425580 CPUtime=7.32
/proc/386/stat : 386 (gringo) R 369 369 1733 0 -1 4202496 101195 0 0 0 690 42 0 0 20 0 1 0 118931024 435793920 84720 18446744073709551615 4194304 6531320 140737224128320 140737224125304 4593145 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/386/statm: 106395 84720 282 571 0 105816 0
Current children cumulated CPU time (s) 12.54
Current children cumulated vsize (KiB) 434792

[startup+25.5005 s]
/proc/loadavg: 0.91 0.98 0.99 2/62 388
/proc/meminfo: memFree=422100/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=18.27
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 806 222443 0 5 1 0 1697 129 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759120 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
[pid=387] ppid=369 vsize=238108 CPUtime=6.46
/proc/387/stat : 387 (clasp) R 369 369 1733 0 -1 4202496 72154 0 22 0 617 29 0 0 20 0 1 0 118932369 243822592 59046 18446744073709551615 4194304 6238623 140735917544256 140735917541280 4586178 0 0 16781316 18946 0 0 0 17 0 0 0 18 0 0
/proc/387/statm: 59527 59046 263 500 0 59024 0
[pid=388] ppid=369 vsize=22040 CPUtime=0.02
/proc/388/stat : 388 (parse.py) S 369 369 1733 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 118932370 22568960 1127 18446744073709551615 4194304 6642060 140737173580304 140737173578664 140607247906592 0 0 16777220 20994 0 0 0 17 0 0 0 18 0 0
/proc/388/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 24.75
Current children cumulated vsize (KiB) 269360

[startup+51.1005 s]
/proc/loadavg: 0.94 0.98 0.99 2/62 388
/proc/meminfo: memFree=421480/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=18.27
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 806 222443 0 5 1 0 1697 129 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759120 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
[pid=387] ppid=369 vsize=238108 CPUtime=31.8
/proc/387/stat : 387 (clasp) R 369 369 1733 0 -1 4202496 72280 0 22 0 3150 30 0 0 20 0 1 0 118932369 243822592 59172 18446744073709551615 4194304 6238623 140735917544256 140735917541280 4305936 0 0 16781316 18946 0 0 0 17 0 0 0 18 0 0
/proc/387/statm: 59527 59172 264 500 0 59024 0
[pid=388] ppid=369 vsize=22040 CPUtime=0.02
/proc/388/stat : 388 (parse.py) S 369 369 1733 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 118932370 22568960 1127 18446744073709551615 4194304 6642060 140737173580304 140737173578664 140607247906592 0 0 16777220 20994 0 0 0 17 0 0 0 18 0 0
/proc/388/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.09
Current children cumulated vsize (KiB) 269360

[startup+102.3 s]
/proc/loadavg: 1.16 1.03 1.00 2/62 388
/proc/meminfo: memFree=385644/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=18.27
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 806 222443 0 5 1 0 1697 129 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759120 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
[pid=387] ppid=369 vsize=273856 CPUtime=82.49
/proc/387/stat : 387 (clasp) R 369 369 1733 0 -1 4202496 81189 0 22 0 8216 33 0 0 20 0 1 0 118932369 280428544 68081 18446744073709551615 4194304 6238623 140735917544256 140735917540808 4669522 0 0 16781316 18946 0 0 0 17 0 0 0 18 0 0
/proc/387/statm: 68464 68081 264 500 0 67961 0
[pid=388] ppid=369 vsize=22040 CPUtime=0.02
/proc/388/stat : 388 (parse.py) S 369 369 1733 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 118932370 22568960 1127 18446744073709551615 4194304 6642060 140737173580304 140737173578664 140607247906592 0 0 16777220 20994 0 0 0 17 0 0 0 18 0 0
/proc/388/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 100.78
Current children cumulated vsize (KiB) 305108

[startup+162.3 s]
/proc/loadavg: 1.06 1.02 1.00 2/62 388
/proc/meminfo: memFree=326620/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=18.27
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 806 222443 0 5 1 0 1697 129 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759120 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
[pid=387] ppid=369 vsize=332776 CPUtime=141.87
/proc/387/stat : 387 (clasp) R 369 369 1733 0 -1 4202496 95902 0 22 0 14145 42 0 0 20 0 1 0 118932369 340762624 82794 18446744073709551615 4194304 6238623 140735917544256 140735917540808 4306741 0 0 16781316 18946 0 0 0 17 0 0 0 18 0 0
/proc/387/statm: 83194 82794 264 500 0 82691 0
[pid=388] ppid=369 vsize=22040 CPUtime=0.02
/proc/388/stat : 388 (parse.py) S 369 369 1733 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 118932370 22568960 1127 18446744073709551615 4194304 6642060 140737173580304 140737173578664 140607247906592 0 0 16777220 20994 0 0 0 17 0 0 0 18 0 0
/proc/388/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 160.16
Current children cumulated vsize (KiB) 364028

[startup+222.303 s]
/proc/loadavg: 1.08 1.03 1.00 2/62 388
/proc/meminfo: memFree=314592/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=18.27
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 806 222443 0 5 1 0 1697 129 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759120 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
[pid=387] ppid=369 vsize=344896 CPUtime=201.32
/proc/387/stat : 387 (clasp) R 369 369 1733 0 -1 4202496 98937 0 22 0 20087 45 0 0 20 0 1 0 118932369 353173504 85829 18446744073709551615 4194304 6238623 140735917544256 140735917540808 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 18 0 0
/proc/387/statm: 86224 85829 264 500 0 85721 0
[pid=388] ppid=369 vsize=22040 CPUtime=0.02
/proc/388/stat : 388 (parse.py) S 369 369 1733 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 118932370 22568960 1127 18446744073709551615 4194304 6642060 140737173580304 140737173578664 140607247906592 0 0 16777220 20994 0 0 0 17 0 0 0 18 0 0
/proc/388/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 219.61
Current children cumulated vsize (KiB) 376148

[startup+282.3 s]
/proc/loadavg: 1.07 1.04 1.00 2/62 388
/proc/meminfo: memFree=313104/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=18.27
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 806 222443 0 5 1 0 1697 129 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759120 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
[pid=387] ppid=369 vsize=346488 CPUtime=260.88
/proc/387/stat : 387 (clasp) R 369 369 1733 0 -1 4202496 99331 0 22 0 26043 45 0 0 20 0 1 0 118932369 354803712 86223 18446744073709551615 4194304 6238623 140735917544256 140735917540808 4696972 0 0 16781316 18946 0 0 0 17 0 0 0 18 0 0
/proc/387/statm: 86622 86223 264 500 0 86119 0
[pid=388] ppid=369 vsize=22040 CPUtime=0.02
/proc/388/stat : 388 (parse.py) S 369 369 1733 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 118932370 22568960 1127 18446744073709551615 4194304 6642060 140737173580304 140737173578664 140607247906592 0 0 16777220 20994 0 0 0 17 0 0 0 18 0 0
/proc/388/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 279.17
Current children cumulated vsize (KiB) 377740



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+303.4 s]
/proc/loadavg: 1.05 1.03 1.00 3/62 388
/proc/meminfo: memFree=307276/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=18.27
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 806 222443 0 5 1 0 1697 129 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759120 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
[pid=387] ppid=369 vsize=352356 CPUtime=281.8
/proc/387/stat : 387 (clasp) R 369 369 1733 0 -1 4202496 100778 0 22 0 28135 45 0 0 20 0 1 0 118932369 360812544 87670 18446744073709551615 4194304 6238623 140735917544256 140735917540808 4636320 0 0 16781316 18946 0 0 0 17 0 0 0 18 0 0
/proc/387/statm: 88089 87670 264 500 0 87586 0
[pid=388] ppid=369 vsize=22040 CPUtime=0.02
/proc/388/stat : 388 (parse.py) S 369 369 1733 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 118932370 22568960 1127 18446744073709551615 4194304 6642060 140737173580304 140737173578664 140607247906592 0 0 16777220 20994 0 0 0 17 0 0 0 18 0 0
/proc/388/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300.09
Current children cumulated vsize (KiB) 383608

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+303.4 s]
/proc/loadavg: 1.05 1.03 1.00 3/62 388
/proc/meminfo: memFree=307276/1022884 swapFree=0/0
[pid=369] ppid=368 vsize=9212 CPUtime=18.27
/proc/369/stat : 369 (aspcud-full) S 368 369 1733 0 -1 4202496 806 222443 0 5 1 0 1697 129 20 0 1 0 118930494 9433088 365 18446744073709551615 4194304 5129932 140735544761056 140735544759120 139837405197406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/369/statm: 2303 365 303 229 0 63 0
[pid=387] ppid=369 vsize=352356 CPUtime=281.8
/proc/387/stat : 387 (clasp) R 369 369 1733 0 -1 4202496 100778 0 22 0 28135 45 0 0 20 0 1 0 118932369 360812544 87670 18446744073709551615 4194304 6238623 140735917544256 140735917540808 4636320 0 0 16781316 18946 0 0 0 17 0 0 0 18 0 0
/proc/387/statm: 88089 87670 264 500 0 87586 0
[pid=388] ppid=369 vsize=22040 CPUtime=0.02
/proc/388/stat : 388 (parse.py) S 369 369 1733 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 118932370 22568960 1127 18446744073709551615 4194304 6642060 140737173580304 140737173578664 140607247906592 0 0 16777220 20994 0 0 0 17 0 0 0 18 0 0
/proc/388/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300.09
Current children cumulated vsize (KiB) 383608

Child status: 0
Real time (s): 303.475
CPU time (s): 300.183
CPU user time (s): 298.379
CPU system time (s): 1.80411
CPU usage (%): 98.915
Max. virtual memory (cumulated for all children) (KiB): 785388

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.379
system time used= 1.80411
maximum resident set size= 652112
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 325649
page faults= 40
swaps= 0
block input operations= 73600
block output operations= 82296
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 126
involuntary context switches= 34475

runsolver used 0.564035 second user time and 1.5361 second system time

The end