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/easy/rand695.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand695.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/easy/rand695.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.85 0.94 0.97 2/59 1342
/proc/meminfo: memFree=430448/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=3152 CPUtime=0
/proc/1342/stat : 1342 (runsolver) R 1340 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119410790 3227648 32 18446744073709551615 134512640 134586868 4288310096 4288308144 4151575600 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.178276 s]
/proc/loadavg: 0.85 0.94 0.97 2/59 1342
/proc/meminfo: memFree=430448/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=0.02
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 738 3615 0 0 0 0 2 0 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887273120 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200322 s]
/proc/loadavg: 0.85 0.94 0.97 2/59 1342
/proc/meminfo: memFree=430448/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=0.02
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 738 3615 0 0 0 0 2 0 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887273120 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300301 s]
/proc/loadavg: 0.85 0.94 0.97 2/59 1342
/proc/meminfo: memFree=430448/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=0.02
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 738 3615 0 0 0 0 2 0 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887273120 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700234 s]
/proc/loadavg: 0.85 0.94 0.97 2/59 1342
/proc/meminfo: memFree=430448/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=0.02
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 738 3615 0 0 0 0 2 0 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887273120 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.85 0.94 0.97 2/61 1362
/proc/meminfo: memFree=396200/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=0.02
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 738 3615 0 0 0 0 2 0 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887273120 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
[pid=1362] ppid=1342 vsize=48864 CPUtime=1.43
/proc/1362/stat : 1362 (cudf2lp) R 1342 1342 1733 0 -1 4202496 13688 0 1 0 134 9 0 0 20 0 1 0 119410793 50036736 10290 18446744073709551615 4194304 5690517 140735679655792 140735679653432 4961219 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/1362/statm: 12216 10290 159 366 0 11847 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 58076

[startup+3.10034 s]
/proc/loadavg: 0.87 0.94 0.97 2/61 1362
/proc/meminfo: memFree=365324/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=0.02
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 738 3615 0 0 0 0 2 0 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887273120 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
[pid=1362] ppid=1342 vsize=72092 CPUtime=3.01
/proc/1362/stat : 1362 (cudf2lp) R 1342 1342 1733 0 -1 4202496 23823 0 1 0 285 16 0 0 20 0 1 0 119410793 73822208 17760 18446744073709551615 4194304 5690517 140735679655792 140735679652808 4951912 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/1362/statm: 18023 17760 174 366 0 17654 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 81304

[startup+6.30031 s]
/proc/loadavg: 0.87 0.94 0.97 2/61 1363
/proc/meminfo: memFree=302084/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=3.1
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 764 27440 0 1 0 0 292 18 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887273120 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
[pid=1363] ppid=1342 vsize=161600 CPUtime=3.1
/proc/1363/stat : 1363 (gringo) R 1342 1342 1733 0 -1 4202496 40705 0 0 0 286 24 0 0 20 0 1 0 119411106 165478400 36262 18446744073709551615 4194304 6531320 140733872586080 140733872583064 4592496 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/1363/statm: 40400 36262 281 571 0 39821 0
Current children cumulated CPU time (s) 6.2
Current children cumulated vsize (KiB) 170812

[startup+12.7004 s]
/proc/loadavg: 0.89 0.94 0.97 2/62 1365
/proc/meminfo: memFree=268596/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=10.41
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 806 135194 0 1 0 0 954 87 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887272528 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
[pid=1364] ppid=1342 vsize=137764 CPUtime=2.04
/proc/1364/stat : 1364 (clasp) R 1342 1342 1733 0 -1 4202496 40147 0 0 0 188 16 0 0 20 0 1 0 119411851 141070336 33988 18446744073709551615 4194304 6238623 140734309428048 140734309425072 4676786 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1364/statm: 34441 33988 263 500 0 33938 0
[pid=1365] ppid=1342 vsize=22040 CPUtime=0.02
/proc/1365/stat : 1365 (parse.py) S 1342 1342 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119411851 22568960 1128 18446744073709551615 4194304 6642060 140736773116800 140736773115160 140207339812640 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1365/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 169016

[startup+25.5004 s]
/proc/loadavg: 0.90 0.94 0.97 2/62 1365
/proc/meminfo: memFree=268100/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=10.41
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 806 135194 0 1 0 0 954 87 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887272528 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
[pid=1364] ppid=1342 vsize=137764 CPUtime=14.71
/proc/1364/stat : 1364 (clasp) R 1342 1342 1733 0 -1 4202496 40294 0 0 0 1455 16 0 0 20 0 1 0 119411851 141070336 34135 18446744073709551615 4194304 6238623 140734309428048 140734309425072 4669522 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1364/statm: 34441 34135 264 500 0 33938 0
[pid=1365] ppid=1342 vsize=22040 CPUtime=0.02
/proc/1365/stat : 1365 (parse.py) S 1342 1342 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119411851 22568960 1128 18446744073709551615 4194304 6642060 140736773116800 140736773115160 140207339812640 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1365/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.14
Current children cumulated vsize (KiB) 169016

[startup+51.1004 s]
/proc/loadavg: 0.93 0.95 0.97 2/62 1365
/proc/meminfo: memFree=268100/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=10.41
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 806 135194 0 1 0 0 954 87 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887272528 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
[pid=1364] ppid=1342 vsize=137764 CPUtime=40.06
/proc/1364/stat : 1364 (clasp) R 1342 1342 1733 0 -1 4202496 40294 0 0 0 3988 18 0 0 20 0 1 0 119411851 141070336 34135 18446744073709551615 4194304 6238623 140734309428048 140734309425072 4687675 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1364/statm: 34441 34135 264 500 0 33938 0
[pid=1365] ppid=1342 vsize=22040 CPUtime=0.02
/proc/1365/stat : 1365 (parse.py) S 1342 1342 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119411851 22568960 1128 18446744073709551615 4194304 6642060 140736773116800 140736773115160 140207339812640 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1365/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.49
Current children cumulated vsize (KiB) 169016

[startup+102.3 s]
/proc/loadavg: 0.97 0.95 0.97 2/62 1365
/proc/meminfo: memFree=168900/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=10.41
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 806 135194 0 1 0 0 954 87 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887272528 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
[pid=1364] ppid=1342 vsize=236720 CPUtime=90.86
/proc/1364/stat : 1364 (clasp) R 1342 1342 1733 0 -1 4202496 64997 0 0 0 9056 30 0 0 20 0 1 0 119411851 242401280 58837 18446744073709551615 4194304 6238623 140734309428048 140734309424600 4687972 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1364/statm: 59180 58837 264 500 0 58677 0
[pid=1365] ppid=1342 vsize=22040 CPUtime=0.02
/proc/1365/stat : 1365 (parse.py) S 1342 1342 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119411851 22568960 1128 18446744073709551615 4194304 6642060 140736773116800 140736773115160 140207339812640 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1365/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.29
Current children cumulated vsize (KiB) 267972

[startup+162.3 s]
/proc/loadavg: 1.02 0.97 0.97 2/62 1373
/proc/meminfo: memFree=130956/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=10.41
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 806 135194 0 1 0 0 954 87 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887272528 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
[pid=1364] ppid=1342 vsize=273720 CPUtime=150.39
/proc/1364/stat : 1364 (clasp) R 1342 1342 1733 0 -1 4202496 74277 0 0 0 15006 33 0 0 20 0 1 0 119411851 280289280 68117 18446744073709551615 4194304 6238623 140734309428048 140734309424600 4353078 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1364/statm: 68430 68117 264 500 0 67927 0
[pid=1365] ppid=1342 vsize=22040 CPUtime=0.02
/proc/1365/stat : 1365 (parse.py) S 1342 1342 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119411851 22568960 1128 18446744073709551615 4194304 6642060 140736773116800 140736773115160 140207339812640 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1365/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.82
Current children cumulated vsize (KiB) 304972

[startup+222.303 s]
/proc/loadavg: 1.01 0.97 0.97 2/62 1373
/proc/meminfo: memFree=89664/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=10.41
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 806 135194 0 1 0 0 954 87 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887272528 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
[pid=1364] ppid=1342 vsize=315400 CPUtime=209.97
/proc/1364/stat : 1364 (clasp) R 1342 1342 1733 0 -1 4202496 84695 0 0 0 20960 37 0 0 20 0 1 0 119411851 322969600 78535 18446744073709551615 4194304 6238623 140734309428048 140734309424600 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1364/statm: 78850 78535 264 500 0 78347 0
[pid=1365] ppid=1342 vsize=22040 CPUtime=0.02
/proc/1365/stat : 1365 (parse.py) S 1342 1342 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119411851 22568960 1128 18446744073709551615 4194304 6642060 140736773116800 140736773115160 140207339812640 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1365/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.4
Current children cumulated vsize (KiB) 346652

[startup+282.3 s]
/proc/loadavg: 1.07 0.99 0.98 2/62 1373
/proc/meminfo: memFree=80116/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=10.41
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 806 135194 0 1 0 0 954 87 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887272528 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
[pid=1364] ppid=1342 vsize=324948 CPUtime=269.54
/proc/1364/stat : 1364 (clasp) R 1342 1342 1733 0 -1 4202496 87083 0 0 0 26916 38 0 0 20 0 1 0 119411851 332746752 80923 18446744073709551615 4194304 6238623 140734309428048 140734309424600 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1364/statm: 81237 80923 264 500 0 80734 0
[pid=1365] ppid=1342 vsize=22040 CPUtime=0.02
/proc/1365/stat : 1365 (parse.py) S 1342 1342 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119411851 22568960 1128 18446744073709551615 4194304 6642060 140736773116800 140736773115160 140207339812640 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1365/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.97
Current children cumulated vsize (KiB) 356200



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.5 s]
/proc/loadavg: 1.05 0.99 0.98 2/62 1373
/proc/meminfo: memFree=75156/1022884 swapFree=0/0
[pid=1342] ppid=1340 vsize=9212 CPUtime=10.41
/proc/1342/stat : 1342 (aspcud-full) S 1340 1342 1733 0 -1 4202496 806 135194 0 1 0 0 954 87 20 0 1 0 119410790 9433088 364 18446744073709551615 4194304 5129932 140734887274464 140734887272528 140551092552798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/1342/statm: 2303 364 303 229 0 63 0
[pid=1364] ppid=1342 vsize=329848 CPUtime=289.6
/proc/1364/stat : 1364 (clasp) R 1342 1342 1733 0 -1 4202496 88308 0 0 0 28922 38 0 0 20 0 1 0 119411851 337764352 82148 18446744073709551615 4194304 6238623 140734309428048 140734309424600 4306761 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1364/statm: 82462 82148 264 500 0 81959 0
[pid=1365] ppid=1342 vsize=22040 CPUtime=0.02
/proc/1365/stat : 1365 (parse.py) S 1342 1342 1733 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119411851 22568960 1128 18446744073709551615 4194304 6642060 140736773116800 140736773115160 140207339812640 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1365/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.03
Current children cumulated vsize (KiB) 361100

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): 302.548
CPU time (s): 300.091
CPU user time (s): 298.779
CPU system time (s): 1.31208
CPU usage (%): 99.1878
Max. virtual memory (cumulated for all children) (KiB): 456708

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.779
system time used= 1.31208
maximum resident set size= 396840
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 225945
page faults= 1
swaps= 0
block input operations= 42504
block output operations= 46792
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 72
involuntary context switches= 34417

runsolver used 0.48803 second user time and 1.23608 second system time

The end