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/aspuncud-full-1.7/trendy-size/upgrade/easy/rand268.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/upgrade/easy/rand268.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/trendy-size/upgrade/easy/rand268.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: 1.07 1.02 0.94 2/64 17740
/proc/meminfo: memFree=437560/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9204 CPUtime=0
/proc/17740/stat : 17740 (aspuncud-full) R 17739 17740 1745 0 -1 4202496 424 0 0 0 0 0 0 0 20 0 1 0 119704457 9424896 331 18446744073709551615 4194304 5129932 140734700867824 140734700865064 140211438655280 0 65536 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2301 331 271 229 0 61 0

[startup+0.204884 s]
/proc/loadavg: 1.07 1.02 0.94 2/64 17740
/proc/meminfo: memFree=437560/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9212 CPUtime=0.03
/proc/17740/stat : 17740 (aspuncud-full) S 17739 17740 1745 0 -1 4202496 697 2808 0 0 0 0 3 0 20 0 1 0 119704457 9433088 365 18446744073709551615 4194304 5129932 140734700867824 140734700866480 140211439141982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300321 s]
/proc/loadavg: 1.07 1.02 0.94 2/64 17740
/proc/meminfo: memFree=437560/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9212 CPUtime=0.03
/proc/17740/stat : 17740 (aspuncud-full) S 17739 17740 1745 0 -1 4202496 697 2808 0 0 0 0 3 0 20 0 1 0 119704457 9433088 365 18446744073709551615 4194304 5129932 140734700867824 140734700866480 140211439141982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.400312 s]
/proc/loadavg: 1.07 1.02 0.94 2/64 17740
/proc/meminfo: memFree=437560/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9212 CPUtime=0.03
/proc/17740/stat : 17740 (aspuncud-full) S 17739 17740 1745 0 -1 4202496 697 2808 0 0 0 0 3 0 20 0 1 0 119704457 9433088 365 18446744073709551615 4194304 5129932 140734700867824 140734700866480 140211439141982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.70023 s]
/proc/loadavg: 1.07 1.02 0.94 2/64 17740
/proc/meminfo: memFree=437560/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9212 CPUtime=0.03
/proc/17740/stat : 17740 (aspuncud-full) S 17739 17740 1745 0 -1 4202496 697 2808 0 0 0 0 3 0 20 0 1 0 119704457 9433088 365 18446744073709551615 4194304 5129932 140734700867824 140734700866480 140211439141982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50026 s]
/proc/loadavg: 1.07 1.02 0.94 2/66 17753
/proc/meminfo: memFree=404552/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9212 CPUtime=0.03
/proc/17740/stat : 17740 (aspuncud-full) S 17739 17740 1745 0 -1 4202496 697 2808 0 0 0 0 3 0 20 0 1 0 119704457 9433088 365 18446744073709551615 4194304 5129932 140734700867824 140734700866480 140211439141982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2303 365 303 229 0 63 0
[pid=17753] ppid=17740 vsize=28876 CPUtime=1.25
/proc/17753/stat : 17753 (cudf2lp) R 17740 17740 1745 0 -1 4202496 8580 0 0 0 121 4 0 0 20 0 1 0 119704467 29569024 6848 18446744073709551615 4194304 5690517 140737122025360 140737122023000 4357501 0 0 16781316 0 0 0 0 17 0 0 0 12 0 0
/proc/17753/statm: 7219 6848 159 366 0 6850 0
Current children cumulated CPU time (s) 1.28
Current children cumulated vsize (KiB) 38088

[startup+3.10032 s]
/proc/loadavg: 1.07 1.02 0.94 2/66 17753
/proc/meminfo: memFree=374048/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9212 CPUtime=0.03
/proc/17740/stat : 17740 (aspuncud-full) S 17739 17740 1745 0 -1 4202496 697 2808 0 0 0 0 3 0 20 0 1 0 119704457 9433088 365 18446744073709551615 4194304 5129932 140734700867824 140734700866480 140211439141982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2303 365 303 229 0 63 0
[pid=17753] ppid=17740 vsize=72092 CPUtime=2.84
/proc/17753/stat : 17753 (cudf2lp) R 17740 17740 1745 0 -1 4202496 23821 0 0 0 271 13 0 0 20 0 1 0 119704467 73822208 17759 18446744073709551615 4194304 5690517 140737122025360 140737122022568 4991228 0 0 16781316 0 0 0 0 17 0 0 0 13 0 0
/proc/17753/statm: 18023 17759 174 366 0 17654 0
Current children cumulated CPU time (s) 2.87
Current children cumulated vsize (KiB) 81304

[startup+6.30025 s]
/proc/loadavg: 1.07 1.02 0.94 2/66 17754
/proc/meminfo: memFree=327548/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9212 CPUtime=3.21
/proc/17740/stat : 17740 (aspuncud-full) S 17739 17740 1745 0 -1 4202496 725 26631 0 0 0 0 304 17 20 0 1 0 119704457 9433088 365 18446744073709551615 4194304 5129932 140734700867824 140734700866480 140211439141982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2303 365 303 229 0 63 0
[pid=17754] ppid=17740 vsize=157204 CPUtime=2.83
/proc/17754/stat : 17754 (gringo) R 17740 17740 1745 0 -1 4202496 39715 0 0 0 260 23 0 0 20 0 1 0 119704800 160976896 35273 18446744073709551615 4194304 6531320 140736340182384 140736340178312 4595408 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17754/statm: 39301 35273 281 571 0 38722 0
Current children cumulated CPU time (s) 6.04
Current children cumulated vsize (KiB) 166416

[startup+12.7003 s]
/proc/loadavg: 1.06 1.02 0.94 2/67 17756
/proc/meminfo: memFree=273432/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9212 CPUtime=9
/proc/17740/stat : 17740 (aspuncud-full) S 17739 17740 1745 0 -1 4202496 766 135231 0 0 0 0 830 70 20 0 1 0 119704457 9433088 365 18446744073709551615 4194304 5129932 140734700867824 140734700865888 140211439141982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2303 365 303 229 0 63 0
[pid=17755] ppid=17740 vsize=136436 CPUtime=3.34
/proc/17755/stat : 17755 (unclasp) R 17740 17740 1745 0 -1 4202496 39706 0 0 0 324 10 0 0 20 0 1 0 119705387 139710464 33576 18446744073709551615 4194304 6012874 140736149473744 140736149473064 4855815 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17755/statm: 34109 33576 226 444 0 33657 0
[pid=17756] ppid=17740 vsize=22328 CPUtime=0
/proc/17756/stat : 17756 (parse.py) S 17740 17740 1745 0 -1 4202496 1382 0 0 0 0 0 0 0 20 0 1 0 119705387 22863872 1191 18446744073709551615 4194304 6642060 140734687969472 140734687967640 139681623590688 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17756/statm: 5582 1191 508 598 0 668 0
Current children cumulated CPU time (s) 12.34
Current children cumulated vsize (KiB) 167976

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

[startup+12.9003 s]
/proc/loadavg: 1.06 1.02 0.94 2/67 17756
/proc/meminfo: memFree=273432/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9212 CPUtime=9
/proc/17740/stat : 17740 (aspuncud-full) S 17739 17740 1745 0 -1 4202496 766 135231 0 0 0 0 830 70 20 0 1 0 119704457 9433088 365 18446744073709551615 4194304 5129932 140734700867824 140734700865888 140211439141982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2303 365 303 229 0 63 0
[pid=17755] ppid=17740 vsize=136436 CPUtime=3.54
/proc/17755/stat : 17755 (unclasp) R 17740 17740 1745 0 -1 4202496 39706 0 0 0 344 10 0 0 20 0 1 0 119705387 139710464 33576 18446744073709551615 4194304 6012874 140736149473744 140736149473064 4855815 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17755/statm: 34109 33576 226 444 0 33657 0
[pid=17756] ppid=17740 vsize=22328 CPUtime=0
/proc/17756/stat : 17756 (parse.py) S 17740 17740 1745 0 -1 4202496 1382 0 0 0 0 0 0 0 20 0 1 0 119705387 22863872 1191 18446744073709551615 4194304 6642060 140734687969472 140734687967640 139681623590688 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17756/statm: 5582 1191 508 598 0 668 0
Current children cumulated CPU time (s) 12.54
Current children cumulated vsize (KiB) 167976

[startup+13.7003 s]
/proc/loadavg: 1.06 1.01 0.94 2/67 17756
/proc/meminfo: memFree=273432/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9212 CPUtime=9
/proc/17740/stat : 17740 (aspuncud-full) S 17739 17740 1745 0 -1 4202496 766 135231 0 0 0 0 830 70 20 0 1 0 119704457 9433088 365 18446744073709551615 4194304 5129932 140734700867824 140734700865888 140211439141982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2303 365 303 229 0 63 0
[pid=17755] ppid=17740 vsize=136436 CPUtime=4.33
/proc/17755/stat : 17755 (unclasp) R 17740 17740 1745 0 -1 4202496 39706 0 0 0 422 11 0 0 20 0 1 0 119705387 139710464 33576 18446744073709551615 4194304 6012874 140736149473744 140736149473064 4548105 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17755/statm: 34109 33576 226 444 0 33657 0
[pid=17756] ppid=17740 vsize=22328 CPUtime=0
/proc/17756/stat : 17756 (parse.py) S 17740 17740 1745 0 -1 4202496 1382 0 0 0 0 0 0 0 20 0 1 0 119705387 22863872 1191 18446744073709551615 4194304 6642060 140734687969472 140734687967640 139681623590688 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17756/statm: 5582 1191 508 598 0 668 0
Current children cumulated CPU time (s) 13.33
Current children cumulated vsize (KiB) 167976

[startup+14.5035 s]
/proc/loadavg: 1.06 1.01 0.94 2/67 17756
/proc/meminfo: memFree=273432/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9212 CPUtime=9
/proc/17740/stat : 17740 (aspuncud-full) S 17739 17740 1745 0 -1 4202496 766 135231 0 0 0 0 830 70 20 0 1 0 119704457 9433088 365 18446744073709551615 4194304 5129932 140734700867824 140734700865888 140211439141982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2303 365 303 229 0 63 0
[pid=17755] ppid=17740 vsize=136436 CPUtime=5.13
/proc/17755/stat : 17755 (unclasp) R 17740 17740 1745 0 -1 4202496 39706 0 0 0 502 11 0 0 20 0 1 0 119705387 139710464 33576 18446744073709551615 4194304 6012874 140736149473744 140736149473064 4548105 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17755/statm: 34109 33576 226 444 0 33657 0
[pid=17756] ppid=17740 vsize=22328 CPUtime=0
/proc/17756/stat : 17756 (parse.py) S 17740 17740 1745 0 -1 4202496 1382 0 0 0 0 0 0 0 20 0 1 0 119705387 22863872 1191 18446744073709551615 4194304 6642060 140734687969472 140734687967640 139681623590688 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17756/statm: 5582 1191 508 598 0 668 0
Current children cumulated CPU time (s) 14.13
Current children cumulated vsize (KiB) 167976

[startup+14.7003 s]
/proc/loadavg: 1.06 1.01 0.94 2/67 17756
/proc/meminfo: memFree=273432/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9212 CPUtime=9
/proc/17740/stat : 17740 (aspuncud-full) S 17739 17740 1745 0 -1 4202496 766 135231 0 0 0 0 830 70 20 0 1 0 119704457 9433088 365 18446744073709551615 4194304 5129932 140734700867824 140734700865888 140211439141982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2303 365 303 229 0 63 0
[pid=17755] ppid=17740 vsize=136436 CPUtime=5.33
/proc/17755/stat : 17755 (unclasp) R 17740 17740 1745 0 -1 4202496 39706 0 0 0 522 11 0 0 20 0 1 0 119705387 139710464 33576 18446744073709551615 4194304 6012874 140736149473744 140736149473064 4855815 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17755/statm: 34109 33576 226 444 0 33657 0
[pid=17756] ppid=17740 vsize=22328 CPUtime=0
/proc/17756/stat : 17756 (parse.py) S 17740 17740 1745 0 -1 4202496 1382 0 0 0 0 0 0 0 20 0 1 0 119705387 22863872 1191 18446744073709551615 4194304 6642060 140734687969472 140734687967640 139681623590688 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17756/statm: 5582 1191 508 598 0 668 0
Current children cumulated CPU time (s) 14.33
Current children cumulated vsize (KiB) 167976

[startup+14.8008 s]
/proc/loadavg: 1.06 1.01 0.94 2/67 17756
/proc/meminfo: memFree=273432/1022884 swapFree=0/0
[pid=17740] ppid=17739 vsize=9212 CPUtime=9
/proc/17740/stat : 17740 (aspuncud-full) S 17739 17740 1745 0 -1 4202496 766 135231 0 0 0 0 830 70 20 0 1 0 119704457 9433088 365 18446744073709551615 4194304 5129932 140734700867824 140734700865888 140211439141982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17740/statm: 2303 365 303 229 0 63 0
[pid=17755] ppid=17740 vsize=103228 CPUtime=5.43
/proc/17755/stat : 17755 (unclasp) R 17740 17740 1745 0 -1 4202496 39714 0 0 0 529 14 0 0 20 0 1 0 119705387 105705472 6993 18446744073709551615 4194304 6012874 140736149473744 140736149473144 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17755/statm: 25807 6993 234 444 0 25355 0
[pid=17756] ppid=17740 vsize=22328 CPUtime=0
/proc/17756/stat : 17756 (parse.py) S 17740 17740 1745 0 -1 4202496 1382 0 0 0 0 0 0 0 20 0 1 0 119705387 22863872 1191 18446744073709551615 4194304 6642060 140734687969472 140734687967672 139681623590688 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17756/statm: 5582 1191 508 598 0 668 0
Current children cumulated CPU time (s) 14.43
Current children cumulated vsize (KiB) 134768

Child status: 0
Real time (s): 14.8197
CPU time (s): 14.4849
CPU user time (s): 13.6088
CPU system time (s): 0.876054
CPU usage (%): 97.7411
Max. virtual memory (cumulated for all children) (KiB): 458584

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.6089
system time used= 0.876054
maximum resident set size= 400228
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 177379
page faults= 0
swaps= 0
block input operations= 42376
block output operations= 47216
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 144
involuntary context switches= 1770

runsolver used 0.032002 second user time and 0.064004 second system time

The end