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/install/rand943.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/install/rand943.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/trendy-size/install/rand943.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.97 0.95 2/60 23848
/proc/meminfo: memFree=725856/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=3152 CPUtime=0
/proc/23848/stat : 23848 (runsolver) R 23847 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 41456810 3227648 33 18446744073709551615 134512640 134586868 4294029328 4294027376 4151510064 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/23848/statm: 788 33 0 19 0 73 0

[startup+0.110552 s]
/proc/loadavg: 0.87 0.97 0.95 2/60 23848
/proc/meminfo: memFree=725856/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=0.02
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 646 2271 2 3 0 0 2 0 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716704 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.20034 s]
/proc/loadavg: 0.87 0.97 0.95 2/60 23848
/proc/meminfo: memFree=725856/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=0.05
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 702 2802 2 4 1 0 3 1 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716704 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300264 s]
/proc/loadavg: 0.87 0.97 0.95 2/60 23848
/proc/meminfo: memFree=725856/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=0.05
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 702 2802 2 4 1 0 3 1 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716704 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700198 s]
/proc/loadavg: 0.87 0.97 0.95 2/60 23848
/proc/meminfo: memFree=725856/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=0.05
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 702 2802 2 4 1 0 3 1 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716704 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50038 s]
/proc/loadavg: 0.87 0.97 0.95 2/62 23861
/proc/meminfo: memFree=674752/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=0.05
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 702 2802 2 4 1 0 3 1 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716704 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
[pid=23861] ppid=23848 vsize=50676 CPUtime=1.32
/proc/23861/stat : 23861 (cudf2lp) R 23848 23848 32685 0 -1 4202496 14850 0 1 0 124 8 0 0 20 0 1 0 41456822 51892224 11453 18446744073709551615 4194304 5690517 140735686900208 140735686897880 5058400 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/23861/statm: 12669 11453 160 366 0 12300 0
Current children cumulated CPU time (s) 1.37
Current children cumulated vsize (KiB) 59888

[startup+3.10034 s]
/proc/loadavg: 0.87 0.97 0.95 2/62 23861
/proc/meminfo: memFree=644496/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=0.05
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 702 2802 2 4 1 0 3 1 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716704 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
[pid=23861] ppid=23848 vsize=93028 CPUtime=2.87
/proc/23861/stat : 23861 (cudf2lp) R 23848 23848 32685 0 -1 4202496 27282 0 1 0 272 15 0 0 20 0 1 0 41456822 95260672 20556 18446744073709551615 4194304 5690517 140735686900208 140735686897848 4293628 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/23861/statm: 23257 20556 160 366 0 22888 0
Current children cumulated CPU time (s) 2.92
Current children cumulated vsize (KiB) 102240

[startup+6.30031 s]
/proc/loadavg: 0.88 0.97 0.95 2/62 23862
/proc/meminfo: memFree=641768/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=4.06
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 731 42122 2 5 1 0 380 25 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716704 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
[pid=23862] ppid=23848 vsize=60064 CPUtime=2.03
/proc/23862/stat : 23862 (gringo) R 23848 23848 32685 0 -1 4202496 15417 0 0 0 190 13 0 0 20 0 1 0 41457235 61505536 13281 18446744073709551615 4194304 6531320 140733425201248 140733425197864 5188057 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23862/statm: 15016 13281 259 571 0 14437 0
Current children cumulated CPU time (s) 6.09
Current children cumulated vsize (KiB) 69276

[startup+12.7003 s]
/proc/loadavg: 0.89 0.97 0.95 2/62 23862
/proc/meminfo: memFree=277332/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=4.06
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 731 42122 2 5 1 0 380 25 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716704 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
[pid=23862] ppid=23848 vsize=548228 CPUtime=8.38
/proc/23862/stat : 23862 (gringo) R 23848 23848 32685 0 -1 4202496 128281 0 0 0 780 58 0 0 20 0 1 0 41457235 561385472 111806 18446744073709551615 4194304 6531320 140733425201248 140733425197672 4597016 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23862/statm: 137057 111806 282 571 0 136478 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 557440

[startup+25.5004 s]
/proc/loadavg: 0.91 0.97 0.95 2/63 23864
/proc/meminfo: memFree=444392/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=15.43
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 772 225584 2 5 1 0 1425 117 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716112 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
[pid=23863] ppid=23848 vsize=236660 CPUtime=9.68
/proc/23863/stat : 23863 (unclasp) R 23848 23848 32685 0 -1 4202496 70678 0 0 0 949 19 0 0 20 0 1 0 41458385 242339840 58004 18446744073709551615 4194304 6012874 140735504290496 140735504289816 4548572 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23863/statm: 59165 58004 230 444 0 58713 0
[pid=23864] ppid=23848 vsize=22544 CPUtime=0.01
/proc/23864/stat : 23864 (parse.py) S 23848 23848 32685 0 -1 4202496 1417 0 0 0 1 0 0 0 20 0 1 0 41458385 23085056 1226 18446744073709551615 4194304 6642060 140733458058784 140733458056952 140712999868192 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23864/statm: 5636 1226 508 598 0 722 0
Current children cumulated CPU time (s) 25.12
Current children cumulated vsize (KiB) 268416

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

[startup+25.6004 s]
/proc/loadavg: 0.91 0.97 0.95 2/63 23864
/proc/meminfo: memFree=444392/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=15.43
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 772 225584 2 5 1 0 1425 117 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716112 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
[pid=23863] ppid=23848 vsize=236660 CPUtime=9.78
/proc/23863/stat : 23863 (unclasp) R 23848 23848 32685 0 -1 4202496 70678 0 0 0 959 19 0 0 20 0 1 0 41458385 242339840 58004 18446744073709551615 4194304 6012874 140735504290496 140735504289816 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23863/statm: 59165 58004 230 444 0 58713 0
[pid=23864] ppid=23848 vsize=22544 CPUtime=0.01
/proc/23864/stat : 23864 (parse.py) S 23848 23848 32685 0 -1 4202496 1417 0 0 0 1 0 0 0 20 0 1 0 41458385 23085056 1226 18446744073709551615 4194304 6642060 140733458058784 140733458056952 140712999868192 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23864/statm: 5636 1226 508 598 0 722 0
Current children cumulated CPU time (s) 25.22
Current children cumulated vsize (KiB) 268416

[startup+32.0034 s]
/proc/loadavg: 0.92 0.97 0.95 2/63 23864
/proc/meminfo: memFree=444392/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=15.43
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 772 225584 2 5 1 0 1425 117 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716112 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
[pid=23863] ppid=23848 vsize=236660 CPUtime=16.14
/proc/23863/stat : 23863 (unclasp) R 23848 23848 32685 0 -1 4202496 70678 0 0 0 1594 20 0 0 20 0 1 0 41458385 242339840 58004 18446744073709551615 4194304 6012874 140735504290496 140735504289816 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23863/statm: 59165 58004 230 444 0 58713 0
[pid=23864] ppid=23848 vsize=22544 CPUtime=0.01
/proc/23864/stat : 23864 (parse.py) S 23848 23848 32685 0 -1 4202496 1417 0 0 0 1 0 0 0 20 0 1 0 41458385 23085056 1226 18446744073709551615 4194304 6642060 140733458058784 140733458056952 140712999868192 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23864/statm: 5636 1226 508 598 0 722 0
Current children cumulated CPU time (s) 31.58
Current children cumulated vsize (KiB) 268416

[startup+35.2003 s]
/proc/loadavg: 0.93 0.97 0.95 2/63 23864
/proc/meminfo: memFree=444392/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=15.43
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 772 225584 2 5 1 0 1425 117 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716112 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
[pid=23863] ppid=23848 vsize=236660 CPUtime=19.31
/proc/23863/stat : 23863 (unclasp) R 23848 23848 32685 0 -1 4202496 70678 0 0 0 1911 20 0 0 20 0 1 0 41458385 242339840 58004 18446744073709551615 4194304 6012874 140735504290496 140735504289816 4548572 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23863/statm: 59165 58004 230 444 0 58713 0
[pid=23864] ppid=23848 vsize=22544 CPUtime=0.01
/proc/23864/stat : 23864 (parse.py) S 23848 23848 32685 0 -1 4202496 1417 0 0 0 1 0 0 0 20 0 1 0 41458385 23085056 1226 18446744073709551615 4194304 6642060 140733458058784 140733458056952 140712999868192 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23864/statm: 5636 1226 508 598 0 722 0
Current children cumulated CPU time (s) 34.75
Current children cumulated vsize (KiB) 268416

[startup+36.0003 s]
/proc/loadavg: 0.93 0.97 0.95 2/63 23864
/proc/meminfo: memFree=444392/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=15.43
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 772 225584 2 5 1 0 1425 117 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716112 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
[pid=23863] ppid=23848 vsize=236660 CPUtime=20.11
/proc/23863/stat : 23863 (unclasp) R 23848 23848 32685 0 -1 4202496 70678 0 0 0 1991 20 0 0 20 0 1 0 41458385 242339840 58004 18446744073709551615 4194304 6012874 140735504290496 140735504289816 4548906 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23863/statm: 59165 58004 230 444 0 58713 0
[pid=23864] ppid=23848 vsize=22544 CPUtime=0.01
/proc/23864/stat : 23864 (parse.py) S 23848 23848 32685 0 -1 4202496 1417 0 0 0 1 0 0 0 20 0 1 0 41458385 23085056 1226 18446744073709551615 4194304 6642060 140733458058784 140733458056952 140712999868192 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23864/statm: 5636 1226 508 598 0 722 0
Current children cumulated CPU time (s) 35.55
Current children cumulated vsize (KiB) 268416

[startup+36.8003 s]
/proc/loadavg: 0.93 0.97 0.95 2/63 23864
/proc/meminfo: memFree=444392/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=15.43
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 772 225584 2 5 1 0 1425 117 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716112 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
[pid=23863] ppid=23848 vsize=236660 CPUtime=20.9
/proc/23863/stat : 23863 (unclasp) R 23848 23848 32685 0 -1 4202496 70678 0 0 0 2070 20 0 0 20 0 1 0 41458385 242339840 58004 18446744073709551615 4194304 6012874 140735504290496 140735504289816 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23863/statm: 59165 58004 230 444 0 58713 0
[pid=23864] ppid=23848 vsize=22544 CPUtime=0.01
/proc/23864/stat : 23864 (parse.py) S 23848 23848 32685 0 -1 4202496 1417 0 0 0 1 0 0 0 20 0 1 0 41458385 23085056 1226 18446744073709551615 4194304 6642060 140733458058784 140733458056952 140712999868192 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23864/statm: 5636 1226 508 598 0 722 0
Current children cumulated CPU time (s) 36.34
Current children cumulated vsize (KiB) 268416

[startup+37.2003 s]
/proc/loadavg: 0.93 0.97 0.95 2/63 23864
/proc/meminfo: memFree=444392/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=15.43
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 772 225584 2 5 1 0 1425 117 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716112 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
[pid=23863] ppid=23848 vsize=236660 CPUtime=21.3
/proc/23863/stat : 23863 (unclasp) R 23848 23848 32685 0 -1 4202496 70678 0 0 0 2110 20 0 0 20 0 1 0 41458385 242339840 58004 18446744073709551615 4194304 6012874 140735504290496 140735504289560 4538940 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23863/statm: 59165 58004 230 444 0 58713 0
[pid=23864] ppid=23848 vsize=22544 CPUtime=0.01
/proc/23864/stat : 23864 (parse.py) S 23848 23848 32685 0 -1 4202496 1417 0 0 0 1 0 0 0 20 0 1 0 41458385 23085056 1226 18446744073709551615 4194304 6642060 140733458058784 140733458056904 140712999868192 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23864/statm: 5636 1226 508 598 0 722 0
Current children cumulated CPU time (s) 36.74
Current children cumulated vsize (KiB) 268416

[startup+37.3011 s]
/proc/loadavg: 0.93 0.97 0.95 2/63 23864
/proc/meminfo: memFree=444392/1022884 swapFree=0/0
[pid=23848] ppid=23847 vsize=9212 CPUtime=15.43
/proc/23848/stat : 23848 (aspuncud-full) S 23847 23848 32685 0 -1 4202496 772 225584 2 5 1 0 1425 117 20 0 1 0 41456810 9433088 365 18446744073709551615 4194304 5129932 140736220718048 140736220716112 140567208461406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/23848/statm: 2303 365 303 229 0 63 0
[pid=23863] ppid=23848 vsize=236660 CPUtime=21.4
/proc/23863/stat : 23863 (unclasp) R 23848 23848 32685 0 -1 4202496 70685 0 0 0 2118 22 0 0 20 0 1 0 41458385 242339840 45723 18446744073709551615 4194304 6012874 140735504290496 140735504289896 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23863/statm: 59165 45723 237 444 0 58713 0
[pid=23864] ppid=23848 vsize=22544 CPUtime=0.01
/proc/23864/stat : 23864 (parse.py) S 23848 23848 32685 0 -1 4202496 1417 0 0 0 1 0 0 0 20 0 1 0 41458385 23085056 1226 18446744073709551615 4194304 6642060 140733458058784 140733458056984 140712999868192 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23864/statm: 5636 1226 508 598 0 722 0
Current children cumulated CPU time (s) 36.84
Current children cumulated vsize (KiB) 268416

Child status: 0
Real time (s): 37.3817
CPU time (s): 36.9423
CPU user time (s): 35.4702
CPU system time (s): 1.47209
CPU usage (%): 98.8247
Max. virtual memory (cumulated for all children) (KiB): 812380

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 35.4702
system time used= 1.47209
maximum resident set size= 667932
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 298744
page faults= 8
swaps= 0
block input operations= 69024
block output operations= 83600
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 200
involuntary context switches= 734

runsolver used 0.104006 second user time and 0.116007 second system time

The end