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/rand984.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand984.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/install/rand984.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.93 1.01 1.00 2/64 15572
/proc/meminfo: memFree=579564/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=3152 CPUtime=0
/proc/15572/stat : 15572 (runsolver) R 15571 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 118881759 3227648 33 18446744073709551615 134512640 134586868 4292580752 4292578800 4151993392 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 788 33 0 19 0 73 0

[startup+0.125784 s]
/proc/loadavg: 0.93 1.01 1.00 2/64 15572
/proc/meminfo: memFree=579564/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=0.06
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 741 3618 0 0 1 0 3 2 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702891024 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.200318 s]
/proc/loadavg: 0.93 1.01 1.00 2/64 15572
/proc/meminfo: memFree=579564/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=0.06
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 741 3618 0 0 1 0 3 2 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702891024 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300306 s]
/proc/loadavg: 0.93 1.01 1.00 2/64 15572
/proc/meminfo: memFree=579564/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=0.06
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 741 3618 0 0 1 0 3 2 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702891024 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.70024 s]
/proc/loadavg: 0.93 1.01 1.00 2/64 15572
/proc/meminfo: memFree=579564/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=0.06
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 741 3618 0 0 1 0 3 2 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702891024 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.93 1.01 1.00 2/66 15588
/proc/meminfo: memFree=545688/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=0.06
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 741 3618 0 0 1 0 3 2 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702891024 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
[pid=15588] ppid=15572 vsize=33064 CPUtime=1.36
/proc/15588/stat : 15588 (cudf2lp) R 15572 15572 1745 0 -1 4202496 9678 0 0 0 131 5 0 0 20 0 1 0 118881763 33857536 7944 18446744073709551615 4194304 5690517 140734089151088 140734089148456 4437037 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/15588/statm: 8266 7944 160 366 0 7897 0
Current children cumulated CPU time (s) 1.42
Current children cumulated vsize (KiB) 42276

[startup+3.10034 s]
/proc/loadavg: 0.93 1.01 1.00 2/66 15588
/proc/meminfo: memFree=513696/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=0.06
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 741 3618 0 0 1 0 3 2 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702891024 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
[pid=15588] ppid=15572 vsize=93028 CPUtime=2.94
/proc/15588/stat : 15588 (cudf2lp) R 15572 15572 1745 0 -1 4202496 26444 0 0 0 280 14 0 0 20 0 1 0 118881763 95260672 19716 18446744073709551615 4194304 5690517 140734089151088 140734089148728 4370709 0 0 16781316 0 0 0 0 17 0 0 0 9 0 0
/proc/15588/statm: 23257 19716 160 366 0 22888 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 102240

[startup+6.30032 s]
/proc/loadavg: 0.93 1.01 1.00 2/66 15589
/proc/meminfo: memFree=525848/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=5.26
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 767 42939 0 0 1 0 493 32 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702891024 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
[pid=15589] ppid=15572 vsize=27436 CPUtime=0.9
/proc/15589/stat : 15589 (gringo) R 15572 15572 1745 0 -1 4202496 7173 0 0 0 86 4 0 0 20 0 1 0 118882298 28094464 6061 18446744073709551615 4194304 6531320 140737316721680 140737316718248 4372957 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15589/statm: 6859 6061 259 571 0 6280 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 36648

[startup+12.7003 s]
/proc/loadavg: 1.02 1.03 1.01 2/66 15589
/proc/meminfo: memFree=242136/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=5.26
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 767 42939 0 0 1 0 493 32 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702891024 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
[pid=15589] ppid=15572 vsize=414156 CPUtime=7.23
/proc/15589/stat : 15589 (gringo) R 15572 15572 1745 0 -1 4202496 98368 0 0 0 680 43 0 0 20 0 1 0 118882298 424095744 81892 18446744073709551615 4194304 6531320 140737316721680 140737316718296 5118882 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15589/statm: 103539 81892 282 571 0 102960 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 423368

[startup+25.5004 s]
/proc/loadavg: 1.02 1.03 1.00 2/67 15591
/proc/meminfo: memFree=438932/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=18.79
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 808 228422 0 0 1 0 1747 131 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702890432 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
[pid=15590] ppid=15572 vsize=244140 CPUtime=5.74
/proc/15590/stat : 15590 (clasp) R 15572 15572 1745 0 -1 4202496 73038 0 22 0 544 30 0 0 20 0 1 0 118883703 249999360 59823 18446744073709551615 4194304 6238623 140735576222288 140735576219312 4636192 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/15590/statm: 61035 59823 263 500 0 60532 0
[pid=15591] ppid=15572 vsize=22040 CPUtime=0.01
/proc/15591/stat : 15591 (parse.py) S 15572 15572 1745 0 -1 4202496 1306 0 13 0 1 0 0 0 20 0 1 0 118883703 22568960 1128 18446744073709551615 4194304 6642060 140737296000112 140737295998472 140281951934240 0 0 16777220 20994 0 0 0 17 0 0 0 21 0 0
/proc/15591/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 24.54
Current children cumulated vsize (KiB) 275392

[startup+51.1004 s]
/proc/loadavg: 1.01 1.02 1.00 2/67 15591
/proc/meminfo: memFree=436080/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=18.79
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 808 228422 0 0 1 0 1747 131 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702890432 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
[pid=15590] ppid=15572 vsize=244140 CPUtime=31.1
/proc/15590/stat : 15590 (clasp) R 15572 15572 1745 0 -1 4202496 73837 0 22 0 3080 30 0 0 20 0 1 0 118883703 249999360 60622 18446744073709551615 4194304 6238623 140735576222288 140735576219312 4687788 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/15590/statm: 61035 60622 264 500 0 60532 0
[pid=15591] ppid=15572 vsize=22040 CPUtime=0.01
/proc/15591/stat : 15591 (parse.py) S 15572 15572 1745 0 -1 4202496 1306 0 13 0 1 0 0 0 20 0 1 0 118883703 22568960 1128 18446744073709551615 4194304 6642060 140737296000112 140737295998472 140281951934240 0 0 16777220 20994 0 0 0 17 0 0 0 21 0 0
/proc/15591/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 49.9
Current children cumulated vsize (KiB) 275392

[startup+102.3 s]
/proc/loadavg: 1.00 1.02 1.00 2/67 15591
/proc/meminfo: memFree=435956/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=18.79
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 808 228422 0 0 1 0 1747 131 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702890432 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
[pid=15590] ppid=15572 vsize=244140 CPUtime=81.79
/proc/15590/stat : 15590 (clasp) R 15572 15572 1745 0 -1 4202496 73837 0 22 0 8148 31 0 0 20 0 1 0 118883703 249999360 60622 18446744073709551615 4194304 6238623 140735576222288 140735576219312 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/15590/statm: 61035 60622 264 500 0 60532 0
[pid=15591] ppid=15572 vsize=22040 CPUtime=0.01
/proc/15591/stat : 15591 (parse.py) S 15572 15572 1745 0 -1 4202496 1306 0 13 0 1 0 0 0 20 0 1 0 118883703 22568960 1128 18446744073709551615 4194304 6642060 140737296000112 140737295998472 140281951934240 0 0 16777220 20994 0 0 0 17 0 0 0 21 0 0
/proc/15591/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 100.59
Current children cumulated vsize (KiB) 275392

[startup+162.3 s]
/proc/loadavg: 1.00 1.01 1.00 2/67 15591
/proc/meminfo: memFree=406940/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=18.79
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 808 228422 0 0 1 0 1747 131 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702890432 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
[pid=15590] ppid=15572 vsize=280048 CPUtime=141.31
/proc/15590/stat : 15590 (clasp) R 15572 15572 1745 0 -1 4202496 82877 0 22 0 14097 34 0 0 20 0 1 0 118883703 286769152 69662 18446744073709551615 4194304 6238623 140735576222288 140735576218840 4413097 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/15590/statm: 70012 69662 264 500 0 69509 0
[pid=15591] ppid=15572 vsize=22040 CPUtime=0.01
/proc/15591/stat : 15591 (parse.py) S 15572 15572 1745 0 -1 4202496 1306 0 13 0 1 0 0 0 20 0 1 0 118883703 22568960 1128 18446744073709551615 4194304 6642060 140737296000112 140737295998472 140281951934240 0 0 16777220 20994 0 0 0 17 0 0 0 21 0 0
/proc/15591/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.11
Current children cumulated vsize (KiB) 311300

[startup+222.312 s]
/proc/loadavg: 1.00 1.01 1.00 2/67 15591
/proc/meminfo: memFree=347048/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=18.79
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 808 228422 0 0 1 0 1747 131 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702890432 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
[pid=15590] ppid=15572 vsize=332856 CPUtime=200.84
/proc/15590/stat : 15590 (clasp) R 15572 15572 1745 0 -1 4202496 96044 0 22 0 20045 39 0 0 20 0 1 0 118883703 340844544 82829 18446744073709551615 4194304 6238623 140735576222288 140735576219312 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/15590/statm: 83214 82829 264 500 0 82711 0
[pid=15591] ppid=15572 vsize=22040 CPUtime=0.01
/proc/15591/stat : 15591 (parse.py) S 15572 15572 1745 0 -1 4202496 1306 0 13 0 1 0 0 0 20 0 1 0 118883703 22568960 1128 18446744073709551615 4194304 6642060 140737296000112 140737295998472 140281951934240 0 0 16777220 20994 0 0 0 17 0 0 0 21 0 0
/proc/15591/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 219.64
Current children cumulated vsize (KiB) 364108

[startup+282.3 s]
/proc/loadavg: 1.06 1.02 1.00 2/67 15591
/proc/meminfo: memFree=330928/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=18.79
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 808 228422 0 0 1 0 1747 131 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702890432 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
[pid=15590] ppid=15572 vsize=349248 CPUtime=260.37
/proc/15590/stat : 15590 (clasp) R 15572 15572 1745 0 -1 4202496 100082 0 22 0 25996 41 0 0 20 0 1 0 118883703 357629952 86867 18446744073709551615 4194304 6238623 140735576222288 140735576218840 4409923 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/15590/statm: 87312 86867 264 500 0 86809 0
[pid=15591] ppid=15572 vsize=22040 CPUtime=0.01
/proc/15591/stat : 15591 (parse.py) S 15572 15572 1745 0 -1 4202496 1306 0 13 0 1 0 0 0 20 0 1 0 118883703 22568960 1128 18446744073709551615 4194304 6642060 140737296000112 140737295998472 140281951934240 0 0 16777220 20994 0 0 0 17 0 0 0 21 0 0
/proc/15591/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.17
Current children cumulated vsize (KiB) 380500



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+303.3 s]
/proc/loadavg: 1.04 1.02 1.00 2/67 15591
/proc/meminfo: memFree=330928/1022884 swapFree=0/0
[pid=15572] ppid=15571 vsize=9212 CPUtime=18.79
/proc/15572/stat : 15572 (aspcud-full) S 15571 15572 1745 0 -1 4202496 808 228422 0 0 1 0 1747 131 20 0 1 0 118881759 9433088 365 18446744073709551615 4194304 5129932 140736702892368 140736702890432 140213539882078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15572/statm: 2303 365 303 229 0 63 0
[pid=15590] ppid=15572 vsize=349248 CPUtime=281.2
/proc/15590/stat : 15590 (clasp) R 15572 15572 1745 0 -1 4202496 100082 0 22 0 28079 41 0 0 20 0 1 0 118883703 357629952 86867 18446744073709551615 4194304 6238623 140735576222288 140735576218840 4696985 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/15590/statm: 87312 86867 264 500 0 86809 0
[pid=15591] ppid=15572 vsize=22040 CPUtime=0.01
/proc/15591/stat : 15591 (parse.py) S 15572 15572 1745 0 -1 4202496 1306 0 13 0 1 0 0 0 20 0 1 0 118883703 22568960 1128 18446744073709551615 4194304 6642060 140737296000112 140737295998472 140281951934240 0 0 16777220 20994 0 0 0 17 0 0 0 21 0 0
/proc/15591/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300
Current children cumulated vsize (KiB) 380500

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.368
CPU time (s): 300.095
CPU user time (s): 298.311
CPU system time (s): 1.78411
CPU usage (%): 98.9209
Max. virtual memory (cumulated for all children) (KiB): 819032

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.311
system time used= 1.78411
maximum resident set size= 676012
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 330935
page faults= 36
swaps= 0
block input operations= 79832
block output operations= 84272
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 141
involuntary context switches= 34440

runsolver used 0.584036 second user time and 1.32808 second system time

The end