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/rand892.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand892.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/easy/rand892.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.85 0.94 0.95 2/64 16542
/proc/meminfo: memFree=431688/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9168 CPUtime=0
/proc/16542/stat : 16542 (aspcud-full) R 16541 16542 1745 0 -1 4202496 398 0 0 0 0 0 0 0 20 0 1 0 119384192 9388032 306 18446744073709551615 4194304 5129932 140735784703376 140735784702744 4419968 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2292 306 255 229 0 52 0

[startup+0.137903 s]
/proc/loadavg: 0.85 0.94 0.95 2/64 16542
/proc/meminfo: memFree=431688/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=0.04
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 741 3618 0 0 0 0 3 1 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784702032 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200314 s]
/proc/loadavg: 0.85 0.94 0.95 2/64 16542
/proc/meminfo: memFree=431688/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=0.04
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 741 3618 0 0 0 0 3 1 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784702032 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300306 s]
/proc/loadavg: 0.85 0.94 0.95 2/64 16542
/proc/meminfo: memFree=431688/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=0.04
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 741 3618 0 0 0 0 3 1 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784702032 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700227 s]
/proc/loadavg: 0.85 0.94 0.95 2/64 16542
/proc/meminfo: memFree=431688/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=0.04
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 741 3618 0 0 0 0 3 1 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784702032 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.85 0.94 0.95 2/66 16558
/proc/meminfo: memFree=398060/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=0.04
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 741 3618 0 0 0 0 3 1 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784702032 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
[pid=16558] ppid=16542 vsize=55524 CPUtime=1.38
/proc/16558/stat : 16558 (cudf2lp) R 16542 16542 1745 0 -1 4202496 13675 0 1 0 130 8 0 0 20 0 1 0 119384196 56856576 11942 18446744073709551615 4194304 5690517 140737374142800 140737374138968 4970403 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/16558/statm: 13881 11942 159 366 0 13512 0
Current children cumulated CPU time (s) 1.42
Current children cumulated vsize (KiB) 64736

[startup+3.10032 s]
/proc/loadavg: 0.85 0.94 0.95 2/66 16558
/proc/meminfo: memFree=367308/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=0.04
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 741 3618 0 0 0 0 3 1 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784702032 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
[pid=16558] ppid=16542 vsize=72092 CPUtime=2.97
/proc/16558/stat : 16558 (cudf2lp) R 16542 16542 1745 0 -1 4202496 23822 0 1 0 281 16 0 0 20 0 1 0 119384196 73822208 17759 18446744073709551615 4194304 5690517 140737374142800 140737374140168 4970346 0 0 16781316 0 0 0 0 17 0 0 0 6 0 0
/proc/16558/statm: 18023 17759 174 366 0 17654 0
Current children cumulated CPU time (s) 3.01
Current children cumulated vsize (KiB) 81304

[startup+6.3003 s]
/proc/loadavg: 0.87 0.94 0.95 2/66 16559
/proc/meminfo: memFree=304688/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=3.14
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 767 27442 0 1 0 0 294 20 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784702032 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
[pid=16559] ppid=16542 vsize=159416 CPUtime=3.03
/proc/16559/stat : 16559 (gringo) R 16542 16542 1745 0 -1 4202496 39917 0 0 0 288 15 0 0 20 0 1 0 119384515 163241984 35474 18446744073709551615 4194304 6531320 140737044965248 140737044961176 5554579 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/16559/statm: 39854 35474 281 571 0 39275 0
Current children cumulated CPU time (s) 6.17
Current children cumulated vsize (KiB) 168628

[startup+12.7004 s]
/proc/loadavg: 0.88 0.94 0.95 2/67 16561
/proc/meminfo: memFree=268100/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=10.52
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 807 135095 0 1 0 0 984 68 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784701440 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
[pid=16560] ppid=16542 vsize=138284 CPUtime=1.92
/proc/16560/stat : 16560 (clasp) R 16542 16542 1745 0 -1 4202496 40174 0 0 0 178 14 0 0 20 0 1 0 119385264 141602816 34019 18446744073709551615 4194304 6238623 140737099286800 140737099283824 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16560/statm: 34571 34019 263 500 0 34068 0
[pid=16561] ppid=16542 vsize=22040 CPUtime=0.01
/proc/16561/stat : 16561 (parse.py) S 16542 16542 1745 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119385264 22568960 1128 18446744073709551615 4194304 6642060 140736391924880 140736391923240 140341763290912 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16561/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.45
Current children cumulated vsize (KiB) 169536

[startup+25.5004 s]
/proc/loadavg: 0.90 0.94 0.95 2/67 16561
/proc/meminfo: memFree=267232/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=10.52
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 807 135095 0 1 0 0 984 68 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784701440 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
[pid=16560] ppid=16542 vsize=138284 CPUtime=14.59
/proc/16560/stat : 16560 (clasp) R 16542 16542 1745 0 -1 4202496 40419 0 0 0 1445 14 0 0 20 0 1 0 119385264 141602816 34264 18446744073709551615 4194304 6238623 140737099286800 140737099283824 4677218 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16560/statm: 34571 34264 264 500 0 34068 0
[pid=16561] ppid=16542 vsize=22040 CPUtime=0.01
/proc/16561/stat : 16561 (parse.py) S 16542 16542 1745 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119385264 22568960 1128 18446744073709551615 4194304 6642060 140736391924880 140736391923240 140341763290912 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16561/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.12
Current children cumulated vsize (KiB) 169536

[startup+51.1004 s]
/proc/loadavg: 0.93 0.94 0.95 2/67 16561
/proc/meminfo: memFree=247144/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=10.52
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 807 135095 0 1 0 0 984 68 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784701440 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
[pid=16560] ppid=16542 vsize=158308 CPUtime=39.93
/proc/16560/stat : 16560 (clasp) R 16542 16542 1745 0 -1 4202496 45417 0 0 0 3976 17 0 0 20 0 1 0 119385264 162107392 39262 18446744073709551615 4194304 6238623 140737099286800 140737099283352 4333030 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16560/statm: 39577 39262 264 500 0 39074 0
[pid=16561] ppid=16542 vsize=22040 CPUtime=0.01
/proc/16561/stat : 16561 (parse.py) S 16542 16542 1745 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119385264 22568960 1128 18446744073709551615 4194304 6642060 140736391924880 140736391923240 140341763290912 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16561/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.46
Current children cumulated vsize (KiB) 189560

[startup+102.3 s]
/proc/loadavg: 0.97 0.95 0.95 2/67 16561
/proc/meminfo: memFree=150672/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=10.52
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 807 135095 0 1 0 0 984 68 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784701440 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
[pid=16560] ppid=16542 vsize=254648 CPUtime=90.72
/proc/16560/stat : 16560 (clasp) R 16542 16542 1745 0 -1 4202496 69475 0 0 0 9049 23 0 0 20 0 1 0 119385264 260759552 63320 18446744073709551615 4194304 6238623 140737099286800 140737099283352 4685014 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16560/statm: 63662 63320 264 500 0 63159 0
[pid=16561] ppid=16542 vsize=22040 CPUtime=0.01
/proc/16561/stat : 16561 (parse.py) S 16542 16542 1745 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119385264 22568960 1128 18446744073709551615 4194304 6642060 140736391924880 140736391923240 140341763290912 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16561/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.25
Current children cumulated vsize (KiB) 285900

[startup+162.3 s]
/proc/loadavg: 0.99 0.96 0.95 2/67 16561
/proc/meminfo: memFree=95740/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=10.52
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 807 135095 0 1 0 0 984 68 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784701440 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
[pid=16560] ppid=16542 vsize=309396 CPUtime=150.26
/proc/16560/stat : 16560 (clasp) R 16542 16542 1745 0 -1 4202496 83152 0 0 0 14995 31 0 0 20 0 1 0 119385264 316821504 76997 18446744073709551615 4194304 6238623 140737099286800 140737099283352 4409884 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16560/statm: 77349 76997 264 500 0 76846 0
[pid=16561] ppid=16542 vsize=22040 CPUtime=0.01
/proc/16561/stat : 16561 (parse.py) S 16542 16542 1745 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119385264 22568960 1128 18446744073709551615 4194304 6642060 140736391924880 140736391923240 140341763290912 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16561/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.79
Current children cumulated vsize (KiB) 340648

[startup+222.303 s]
/proc/loadavg: 0.99 0.96 0.95 2/67 16561
/proc/meminfo: memFree=62880/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=10.52
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 807 135095 0 1 0 0 984 68 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784701440 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
[pid=16560] ppid=16542 vsize=342528 CPUtime=209.8
/proc/16560/stat : 16560 (clasp) R 16542 16542 1745 0 -1 4202496 91394 0 0 0 20944 36 0 0 20 0 1 0 119385264 350748672 85239 18446744073709551615 4194304 6238623 140737099286800 140737099283352 4654188 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16560/statm: 85632 85239 264 500 0 85129 0
[pid=16561] ppid=16542 vsize=22040 CPUtime=0.01
/proc/16561/stat : 16561 (parse.py) S 16542 16542 1745 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119385264 22568960 1128 18446744073709551615 4194304 6642060 140736391924880 140736391923240 140341763290912 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16561/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.33
Current children cumulated vsize (KiB) 373780

[startup+282.3 s]
/proc/loadavg: 0.99 0.97 0.95 2/67 16564
/proc/meminfo: memFree=61516/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=10.52
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 807 135095 0 1 0 0 984 68 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784701440 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
[pid=16560] ppid=16542 vsize=343452 CPUtime=269.34
/proc/16560/stat : 16560 (clasp) R 16542 16542 1745 0 -1 4202496 91628 0 0 0 26898 36 0 0 20 0 1 0 119385264 351694848 85473 18446744073709551615 4194304 6238623 140737099286800 140737099283352 4635208 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16560/statm: 85863 85473 264 500 0 85360 0
[pid=16561] ppid=16542 vsize=22040 CPUtime=0.01
/proc/16561/stat : 16561 (parse.py) S 16542 16542 1745 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119385264 22568960 1128 18446744073709551615 4194304 6642060 140736391924880 140736391923240 140341763290912 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16561/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.87
Current children cumulated vsize (KiB) 374704



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+308.3 s]
/proc/loadavg: 1.19 1.02 0.96 2/67 16815
/proc/meminfo: memFree=22152/1022884 swapFree=0/0
[pid=16542] ppid=16541 vsize=9212 CPUtime=10.52
/proc/16542/stat : 16542 (aspcud-full) S 16541 16542 1745 0 -1 4202496 807 135095 0 1 0 0 984 68 20 0 1 0 119384192 9433088 365 18446744073709551615 4194304 5129932 140735784703376 140735784701440 140449563845726 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16542/statm: 2303 365 303 229 0 63 0
[pid=16560] ppid=16542 vsize=344380 CPUtime=289.47
/proc/16560/stat : 16560 (clasp) R 16542 16542 1745 0 -1 4202496 91869 0 0 0 28911 36 0 0 20 0 1 0 119385264 352645120 85714 18446744073709551615 4194304 6238623 140737099286800 140737099283352 4654170 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16560/statm: 86095 85714 264 500 0 85592 0
[pid=16561] ppid=16542 vsize=22040 CPUtime=0.01
/proc/16561/stat : 16561 (parse.py) S 16542 16542 1745 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 119385264 22568960 1128 18446744073709551615 4194304 6642060 140736391924880 140736391923240 140341763290912 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16561/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300
Current children cumulated vsize (KiB) 375632

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): 308.346
CPU time (s): 300.087
CPU user time (s): 298.983
CPU system time (s): 1.10407
CPU usage (%): 97.3214
Max. virtual memory (cumulated for all children) (KiB): 456544

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.983
system time used= 1.10407
maximum resident set size= 396436
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 229409
page faults= 1
swaps= 0
block input operations= 42512
block output operations= 46736
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 78
involuntary context switches= 36320

runsolver used 0.608038 second user time and 1.24408 second system time

The end