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/upgrade/install/rand30.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/install/rand30.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/upgrade/install/rand30.cudf.result -count(down),-notuptodate(solution),-aligned(solution,source,sourceversion),-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 0.99 0.62 2/57 14894
/proc/meminfo: memFree=523696/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9204 CPUtime=0
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 430 0 0 0 0 0 0 0 20 0 1 0 38897097 9424896 331 18446744073709551615 4194304 5129932 140733443338896 140733443336360 139968683190048 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2301 331 272 229 0 61 0

[startup+0.169061 s]
/proc/loadavg: 1.07 0.99 0.62 2/57 14894
/proc/meminfo: memFree=523696/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9212 CPUtime=0.03
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 702 2805 0 0 0 0 2 1 20 0 1 0 38897097 9433088 364 18446744073709551615 4194304 5129932 140733443338896 140733443337552 139968683045982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200323 s]
/proc/loadavg: 1.07 0.99 0.62 2/57 14894
/proc/meminfo: memFree=523696/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9212 CPUtime=0.03
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 702 2805 0 0 0 0 2 1 20 0 1 0 38897097 9433088 364 18446744073709551615 4194304 5129932 140733443338896 140733443337552 139968683045982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300309 s]
/proc/loadavg: 1.07 0.99 0.62 2/57 14894
/proc/meminfo: memFree=523696/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9212 CPUtime=0.03
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 702 2805 0 0 0 0 2 1 20 0 1 0 38897097 9433088 364 18446744073709551615 4194304 5129932 140733443338896 140733443337552 139968683045982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700227 s]
/proc/loadavg: 1.07 0.99 0.62 2/57 14894
/proc/meminfo: memFree=523696/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9212 CPUtime=0.03
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 702 2805 0 0 0 0 2 1 20 0 1 0 38897097 9433088 364 18446744073709551615 4194304 5129932 140733443338896 140733443337552 139968683045982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 1.07 0.99 0.62 2/59 14907
/proc/meminfo: memFree=488084/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9212 CPUtime=0.03
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 702 2805 0 0 0 0 2 1 20 0 1 0 38897097 9433088 364 18446744073709551615 4194304 5129932 140733443338896 140733443337552 139968683045982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2303 364 303 229 0 63 0
[pid=14907] ppid=14894 vsize=34564 CPUtime=1.43
/proc/14907/stat : 14907 (cudf2lp) R 14894 14894 32685 0 -1 4202496 10083 0 0 0 138 5 0 0 20 0 1 0 38897100 35393536 8350 18446744073709551615 4194304 5690517 140736986919056 140736986916696 4373294 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/14907/statm: 8641 8350 160 366 0 8272 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 43776

[startup+3.10031 s]
/proc/loadavg: 1.07 0.99 0.62 2/59 14907
/proc/meminfo: memFree=454852/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9212 CPUtime=0.03
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 702 2805 0 0 0 0 2 1 20 0 1 0 38897097 9433088 364 18446744073709551615 4194304 5129932 140733443338896 140733443337552 139968683045982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2303 364 303 229 0 63 0
[pid=14907] ppid=14894 vsize=99148 CPUtime=3.01
/proc/14907/stat : 14907 (cudf2lp) R 14894 14894 32685 0 -1 4202496 27959 0 0 0 288 13 0 0 20 0 1 0 38897100 101527552 21232 18446744073709551615 4194304 5690517 140736986919056 140736986916696 4293722 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/14907/statm: 24787 21232 160 366 0 24418 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 108360

[startup+6.30031 s]
/proc/loadavg: 1.14 1.00 0.63 2/59 14908
/proc/meminfo: memFree=469980/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9212 CPUtime=5.32
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 731 44083 0 0 0 0 500 32 20 0 1 0 38897097 9433088 364 18446744073709551615 4194304 5129932 140733443338896 140733443337552 139968683045982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2303 364 303 229 0 63 0
[pid=14908] ppid=14894 vsize=28740 CPUtime=0.91
/proc/14908/stat : 14908 (gringo) R 14894 14894 32685 0 -1 4202496 7939 0 0 0 87 4 0 0 20 0 1 0 38897635 29429760 5831 18446744073709551615 4194304 6531320 140736423211792 140736423207336 4373344 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/14908/statm: 7185 5831 259 571 0 6606 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 37952

[startup+12.7003 s]
/proc/loadavg: 1.21 1.02 0.63 2/59 14908
/proc/meminfo: memFree=143364/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9212 CPUtime=5.32
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 731 44083 0 0 0 0 500 32 20 0 1 0 38897097 9433088 364 18446744073709551615 4194304 5129932 140733443338896 140733443337552 139968683045982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2303 364 303 229 0 63 0
[pid=14908] ppid=14894 vsize=457816 CPUtime=7.26
/proc/14908/stat : 14908 (gringo) R 14894 14894 32685 0 -1 4202496 109265 0 0 0 685 41 0 0 20 0 1 0 38897635 468803584 90768 18446744073709551615 4194304 6531320 140736423211792 140736423207720 5512505 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/14908/statm: 114454 90768 282 571 0 113875 0
Current children cumulated CPU time (s) 12.58
Current children cumulated vsize (KiB) 467028

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

[startup+12.8004 s]
/proc/loadavg: 1.21 1.02 0.63 2/59 14908
/proc/meminfo: memFree=143364/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9212 CPUtime=5.32
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 731 44083 0 0 0 0 500 32 20 0 1 0 38897097 9433088 364 18446744073709551615 4194304 5129932 140733443338896 140733443337552 139968683045982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2303 364 303 229 0 63 0
[pid=14908] ppid=14894 vsize=459356 CPUtime=7.36
/proc/14908/stat : 14908 (gringo) R 14894 14894 32685 0 -1 4202496 109910 0 0 0 694 42 0 0 20 0 1 0 38897635 470380544 91413 18446744073709551615 4194304 6531320 140736423211792 140736423208408 5511104 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/14908/statm: 114839 91413 282 571 0 114260 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 468568

[startup+16.0004 s]
/proc/loadavg: 1.20 1.02 0.63 3/60 14910
/proc/meminfo: memFree=484752/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9212 CPUtime=15.16
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 773 182619 0 0 0 0 1414 102 20 0 1 0 38897097 9433088 364 18446744073709551615 4194304 5129932 140733443338896 140733443336960 139968683045982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2303 364 303 229 0 63 0
[pid=14909] ppid=14894 vsize=128800 CPUtime=0.6
/proc/14909/stat : 14909 (unclasp) R 14894 14894 32685 0 -1 4202496 35920 0 0 0 47 13 0 0 20 0 1 0 38898634 131891200 31737 18446744073709551615 4194304 6012874 140733302342112 140733302338712 4699168 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/14909/statm: 32200 31737 173 444 0 31748 0
[pid=14910] ppid=14894 vsize=22040 CPUtime=0.02
/proc/14910/stat : 14910 (parse.py) S 14894 14894 32685 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 38898634 22568960 1128 18446744073709551615 4194304 6642060 140733722381728 140733722380088 139784698930976 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/14910/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 15.78
Current children cumulated vsize (KiB) 160052

[startup+16.8004 s]
/proc/loadavg: 1.20 1.02 0.63 2/60 14910
/proc/meminfo: memFree=325420/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9212 CPUtime=15.16
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 773 182619 0 0 0 0 1414 102 20 0 1 0 38897097 9433088 364 18446744073709551615 4194304 5129932 140733443338896 140733443336960 139968683045982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2303 364 303 229 0 63 0
[pid=14909] ppid=14894 vsize=174892 CPUtime=1.39
/proc/14909/stat : 14909 (unclasp) R 14894 14894 32685 0 -1 4202496 48356 0 0 0 120 19 0 0 20 0 1 0 38898634 179089408 42122 18446744073709551615 4194304 6012874 140733302342112 140733302340872 4538566 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/14909/statm: 43723 42122 213 444 0 43271 0
[pid=14910] ppid=14894 vsize=22040 CPUtime=0.02
/proc/14910/stat : 14910 (parse.py) S 14894 14894 32685 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 38898634 22568960 1128 18446744073709551615 4194304 6642060 140733722381728 140733722380088 139784698930976 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/14910/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 16.57
Current children cumulated vsize (KiB) 206144

[startup+17.2003 s]
/proc/loadavg: 1.20 1.02 0.63 2/60 14910
/proc/meminfo: memFree=325420/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9212 CPUtime=15.16
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 773 182619 0 0 0 0 1414 102 20 0 1 0 38897097 9433088 364 18446744073709551615 4194304 5129932 140733443338896 140733443336960 139968683045982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2303 364 303 229 0 63 0
[pid=14909] ppid=14894 vsize=162588 CPUtime=1.79
/proc/14909/stat : 14909 (unclasp) R 14894 14894 32685 0 -1 4202496 48396 0 0 0 160 19 0 0 20 0 1 0 38898634 166490112 39832 18446744073709551615 4194304 6012874 140733302342112 140733302341176 4300161 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/14909/statm: 40647 39832 226 444 0 40195 0
[pid=14910] ppid=14894 vsize=22188 CPUtime=0.02
/proc/14910/stat : 14910 (parse.py) S 14894 14894 32685 0 -1 4202496 1332 0 0 0 1 1 0 0 20 0 1 0 38898634 22720512 1141 18446744073709551615 4194304 6642060 140733722381728 140733722379768 139784698930976 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/14910/statm: 5547 1141 508 598 0 633 0
Current children cumulated CPU time (s) 16.97
Current children cumulated vsize (KiB) 193988

[startup+17.4009 s]
/proc/loadavg: 1.20 1.02 0.63 2/60 14910
/proc/meminfo: memFree=325420/1022884 swapFree=0/0
[pid=14894] ppid=14893 vsize=9212 CPUtime=15.16
/proc/14894/stat : 14894 (aspuncud-full) S 14893 14894 32685 0 -1 4202496 773 182619 0 0 0 0 1414 102 20 0 1 0 38897097 9433088 364 18446744073709551615 4194304 5129932 140733443338896 140733443336960 139968683045982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/14894/statm: 2303 364 303 229 0 63 0
[pid=14909] ppid=14894 vsize=162588 CPUtime=1.98
/proc/14909/stat : 14909 (unclasp) R 14894 14894 32685 0 -1 4202496 48404 0 0 0 176 22 0 0 20 0 1 0 38898634 166490112 14240 18446744073709551615 4194304 6012874 140733302342112 140733302341512 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/14909/statm: 40647 14240 234 444 0 40195 0
[pid=14910] ppid=14894 vsize=22332 CPUtime=0.02
/proc/14910/stat : 14910 (parse.py) S 14894 14894 32685 0 -1 4202496 1380 0 0 0 1 1 0 0 20 0 1 0 38898634 22867968 1189 18446744073709551615 4194304 6642060 140733722381728 140733722379976 139784698930976 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/14910/statm: 5583 1189 508 598 0 669 0
Current children cumulated CPU time (s) 17.16
Current children cumulated vsize (KiB) 194132

Child status: 0
Real time (s): 17.4286
CPU time (s): 17.2211
CPU user time (s): 15.925
CPU system time (s): 1.29608
CPU usage (%): 98.8092
Max. virtual memory (cumulated for all children) (KiB): 597696

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 15.925
system time used= 1.29608
maximum resident set size= 480140
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 233464
page faults= 0
swaps= 0
block input operations= 68432
block output operations= 66848
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 157
involuntary context switches= 428

runsolver used 0.064004 second user time and 0.052003 second system time

The end