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/slowlink/install/rand220.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/install/rand220.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/install/rand220.cudf.result -sum(changed,installedsize),-count(removed),-notuptodate(solution),-count(changed) 

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

[startup+0 s]
/proc/loadavg: 0.90 0.97 0.97 2/59 21296
/proc/meminfo: memFree=435952/1022884 swapFree=0/0
[pid=21296] ppid=21295 vsize=3152 CPUtime=0
/proc/21296/stat : 21296 (runsolver) R 21295 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120586171 3227648 32 18446744073709551615 134512640 134586868 4293177232 4293175280 4151682096 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/21296/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.1647 s]
/proc/loadavg: 0.90 0.97 0.97 2/59 21296
/proc/meminfo: memFree=435952/1022884 swapFree=0/0
[pid=21296] ppid=21295 vsize=9212 CPUtime=0.02
/proc/21296/stat : 21296 (aspuncud-full) S 21295 21296 1750 0 -1 4202496 699 2809 0 1 0 0 2 0 20 0 1 0 120586171 9433088 365 18446744073709551615 4194304 5129932 140735957072496 140735957071152 139757909914718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21296/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200274 s]
/proc/loadavg: 0.90 0.97 0.97 2/59 21296
/proc/meminfo: memFree=435952/1022884 swapFree=0/0
[pid=21296] ppid=21295 vsize=9212 CPUtime=0.02
/proc/21296/stat : 21296 (aspuncud-full) S 21295 21296 1750 0 -1 4202496 699 2809 0 1 0 0 2 0 20 0 1 0 120586171 9433088 365 18446744073709551615 4194304 5129932 140735957072496 140735957071152 139757909914718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21296/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300276 s]
/proc/loadavg: 0.90 0.97 0.97 2/59 21296
/proc/meminfo: memFree=435952/1022884 swapFree=0/0
[pid=21296] ppid=21295 vsize=9212 CPUtime=0.02
/proc/21296/stat : 21296 (aspuncud-full) S 21295 21296 1750 0 -1 4202496 699 2809 0 1 0 0 2 0 20 0 1 0 120586171 9433088 365 18446744073709551615 4194304 5129932 140735957072496 140735957071152 139757909914718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21296/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.7002 s]
/proc/loadavg: 0.90 0.97 0.97 2/59 21296
/proc/meminfo: memFree=435952/1022884 swapFree=0/0
[pid=21296] ppid=21295 vsize=9212 CPUtime=0.02
/proc/21296/stat : 21296 (aspuncud-full) S 21295 21296 1750 0 -1 4202496 699 2809 0 1 0 0 2 0 20 0 1 0 120586171 9433088 365 18446744073709551615 4194304 5129932 140735957072496 140735957071152 139757909914718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21296/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50027 s]
/proc/loadavg: 0.90 0.97 0.97 2/61 21309
/proc/meminfo: memFree=380004/1022884 swapFree=0/0
[pid=21296] ppid=21295 vsize=9212 CPUtime=0.02
/proc/21296/stat : 21296 (aspuncud-full) S 21295 21296 1750 0 -1 4202496 699 2809 0 1 0 0 2 0 20 0 1 0 120586171 9433088 365 18446744073709551615 4194304 5129932 140735957072496 140735957071152 139757909914718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21296/statm: 2303 365 303 229 0 63 0
[pid=21309] ppid=21296 vsize=50676 CPUtime=1.37
/proc/21309/stat : 21309 (cudf2lp) R 21296 21296 1750 0 -1 4202496 14942 0 0 0 130 7 0 0 20 0 1 0 120586174 51892224 11543 18446744073709551615 4194304 5690517 140734236360944 140734236358584 5006684 0 0 16781316 0 0 0 0 17 0 0 0 9 0 0
/proc/21309/statm: 12669 11543 160 366 0 12300 0
Current children cumulated CPU time (s) 1.39
Current children cumulated vsize (KiB) 59888

[startup+3.10027 s]
/proc/loadavg: 0.90 0.97 0.97 2/61 21309
/proc/meminfo: memFree=329164/1022884 swapFree=0/0
[pid=21296] ppid=21295 vsize=9212 CPUtime=0.02
/proc/21296/stat : 21296 (aspuncud-full) S 21295 21296 1750 0 -1 4202496 699 2809 0 1 0 0 2 0 20 0 1 0 120586171 9433088 365 18446744073709551615 4194304 5129932 140735957072496 140735957071152 139757909914718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21296/statm: 2303 365 303 229 0 63 0
[pid=21309] ppid=21296 vsize=114764 CPUtime=2.93
/proc/21309/stat : 21309 (cudf2lp) R 21296 21296 1750 0 -1 4202496 39318 0 0 0 276 17 0 0 20 0 1 0 120586174 117518336 28361 18446744073709551615 4194304 5690517 140734236360944 140734236358120 4251168 0 0 16781316 0 0 0 0 17 0 0 0 11 0 0
/proc/21309/statm: 28691 28361 173 366 0 28322 0
Current children cumulated CPU time (s) 2.95
Current children cumulated vsize (KiB) 123976

[startup+6.30025 s]
/proc/loadavg: 0.91 0.97 0.97 2/61 21310
/proc/meminfo: memFree=250672/1022884 swapFree=0/0
[pid=21296] ppid=21295 vsize=9212 CPUtime=3.26
/proc/21296/stat : 21296 (aspuncud-full) S 21295 21296 1750 0 -1 4202496 727 42130 0 1 0 0 305 21 20 0 1 0 120586171 9433088 365 18446744073709551615 4194304 5129932 140735957072496 140735957071152 139757909914718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21296/statm: 2303 365 303 229 0 63 0
[pid=21310] ppid=21296 vsize=248912 CPUtime=2.87
/proc/21310/stat : 21310 (gringo) R 21296 21296 1750 0 -1 4202496 61224 0 0 0 265 22 0 0 20 0 1 0 120586512 254885888 51945 18446744073709551615 4194304 6531320 140736885351040 140736885347384 4598391 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21310/statm: 62228 51945 283 571 0 61649 0
Current children cumulated CPU time (s) 6.13
Current children cumulated vsize (KiB) 258124

[startup+12.7004 s]
/proc/loadavg: 0.92 0.97 0.97 2/62 21312
/proc/meminfo: memFree=277944/1022884 swapFree=0/0
[pid=21296] ppid=21295 vsize=9212 CPUtime=8.43
/proc/21296/stat : 21296 (aspuncud-full) S 21295 21296 1750 0 -1 4202496 768 153354 0 1 0 0 777 66 20 0 1 0 120586171 9433088 365 18446744073709551615 4194304 5129932 140735957072496 140735957070560 139757909914718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21296/statm: 2303 365 303 229 0 63 0
[pid=21311] ppid=21296 vsize=139668 CPUtime=3.97
/proc/21311/stat : 21311 (unclasp) R 21296 21296 1750 0 -1 4202496 40565 0 0 0 383 14 0 0 20 0 1 0 120587038 143020032 34387 18446744073709551615 4194304 6012874 140733589459792 140733589459112 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21311/statm: 34917 34387 226 444 0 34465 0
[pid=21312] ppid=21296 vsize=22044 CPUtime=0.01
/proc/21312/stat : 21312 (parse.py) S 21296 21296 1750 0 -1 4202496 1324 0 0 0 0 1 0 0 20 0 1 0 120587038 22573056 1132 18446744073709551615 4194304 6642060 140735338659520 140735338657720 139708495988512 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21312/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 12.41
Current children cumulated vsize (KiB) 170924

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

[startup+12.8004 s]
/proc/loadavg: 0.92 0.97 0.97 2/62 21312
/proc/meminfo: memFree=277944/1022884 swapFree=0/0
[pid=21296] ppid=21295 vsize=9212 CPUtime=8.43
/proc/21296/stat : 21296 (aspuncud-full) S 21295 21296 1750 0 -1 4202496 768 153354 0 1 0 0 777 66 20 0 1 0 120586171 9433088 365 18446744073709551615 4194304 5129932 140735957072496 140735957070560 139757909914718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21296/statm: 2303 365 303 229 0 63 0
[pid=21311] ppid=21296 vsize=139668 CPUtime=4.07
/proc/21311/stat : 21311 (unclasp) R 21296 21296 1750 0 -1 4202496 40565 0 0 0 393 14 0 0 20 0 1 0 120587038 143020032 34387 18446744073709551615 4194304 6012874 140733589459792 140733589459112 4855815 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21311/statm: 34917 34387 226 444 0 34465 0
[pid=21312] ppid=21296 vsize=22044 CPUtime=0.01
/proc/21312/stat : 21312 (parse.py) S 21296 21296 1750 0 -1 4202496 1324 0 0 0 0 1 0 0 20 0 1 0 120587038 22573056 1132 18446744073709551615 4194304 6642060 140735338659520 140735338657720 139708495988512 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21312/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 12.51
Current children cumulated vsize (KiB) 170924

[startup+13.2004 s]
/proc/loadavg: 0.92 0.97 0.97 2/62 21312
/proc/meminfo: memFree=277944/1022884 swapFree=0/0
[pid=21296] ppid=21295 vsize=9212 CPUtime=8.43
/proc/21296/stat : 21296 (aspuncud-full) S 21295 21296 1750 0 -1 4202496 768 153354 0 1 0 0 777 66 20 0 1 0 120586171 9433088 365 18446744073709551615 4194304 5129932 140735957072496 140735957070560 139757909914718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21296/statm: 2303 365 303 229 0 63 0
[pid=21311] ppid=21296 vsize=139668 CPUtime=4.48
/proc/21311/stat : 21311 (unclasp) R 21296 21296 1750 0 -1 4202496 40565 0 0 0 434 14 0 0 20 0 1 0 120587038 143020032 34387 18446744073709551615 4194304 6012874 140733589459792 140733589459112 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21311/statm: 34917 34387 226 444 0 34465 0
[pid=21312] ppid=21296 vsize=22044 CPUtime=0.01
/proc/21312/stat : 21312 (parse.py) S 21296 21296 1750 0 -1 4202496 1324 0 0 0 0 1 0 0 20 0 1 0 120587038 22573056 1132 18446744073709551615 4194304 6642060 140735338659520 140735338657720 139708495988512 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21312/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 12.92
Current children cumulated vsize (KiB) 170924

[startup+13.6003 s]
/proc/loadavg: 0.92 0.97 0.97 2/62 21312
/proc/meminfo: memFree=277944/1022884 swapFree=0/0
[pid=21296] ppid=21295 vsize=9212 CPUtime=8.43
/proc/21296/stat : 21296 (aspuncud-full) S 21295 21296 1750 0 -1 4202496 768 153354 0 1 0 0 777 66 20 0 1 0 120586171 9433088 365 18446744073709551615 4194304 5129932 140735957072496 140735957070560 139757909914718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21296/statm: 2303 365 303 229 0 63 0
[pid=21311] ppid=21296 vsize=139668 CPUtime=4.87
/proc/21311/stat : 21311 (unclasp) R 21296 21296 1750 0 -1 4202496 40565 0 0 0 473 14 0 0 20 0 1 0 120587038 143020032 34387 18446744073709551615 4194304 6012874 140733589459792 140733589459112 4548533 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21311/statm: 34917 34387 226 444 0 34465 0
[pid=21312] ppid=21296 vsize=22044 CPUtime=0.01
/proc/21312/stat : 21312 (parse.py) S 21296 21296 1750 0 -1 4202496 1324 0 0 0 0 1 0 0 20 0 1 0 120587038 22573056 1132 18446744073709551615 4194304 6642060 140735338659520 140735338657720 139708495988512 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21312/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 13.31
Current children cumulated vsize (KiB) 170924

[startup+13.7013 s]
/proc/loadavg: 0.92 0.97 0.97 2/62 21312
/proc/meminfo: memFree=277944/1022884 swapFree=0/0
[pid=21296] ppid=21295 vsize=9212 CPUtime=8.43
/proc/21296/stat : 21296 (aspuncud-full) S 21295 21296 1750 0 -1 4202496 768 153354 0 1 0 0 777 66 20 0 1 0 120586171 9433088 365 18446744073709551615 4194304 5129932 140735957072496 140735957070560 139757909914718 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21296/statm: 2303 365 303 229 0 63 0
[pid=21311] ppid=21296 vsize=139668 CPUtime=4.97
/proc/21311/stat : 21311 (unclasp) R 21296 21296 1750 0 -1 4202496 40573 0 0 0 480 17 0 0 20 0 1 0 120587038 143020032 10843 18446744073709551615 4194304 6012874 140733589459792 140733589459192 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21311/statm: 34917 10843 234 444 0 34465 0
[pid=21312] ppid=21296 vsize=22196 CPUtime=0.01
/proc/21312/stat : 21312 (parse.py) S 21296 21296 1750 0 -1 4202496 1341 0 0 0 0 1 0 0 20 0 1 0 120587038 22728704 1149 18446744073709551615 4194304 6642060 140735338659520 140735338657720 139708495988512 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21312/statm: 5549 1149 508 598 0 635 0
Current children cumulated CPU time (s) 13.41
Current children cumulated vsize (KiB) 171076

Child status: 0
Real time (s): 13.7246
CPU time (s): 13.4648
CPU user time (s): 12.5808
CPU system time (s): 0.884055
CPU usage (%): 98.107
Max. virtual memory (cumulated for all children) (KiB): 477880

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.5808
system time used= 0.884055
maximum resident set size= 407764
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 196325
page faults= 1
swaps= 0
block input operations= 65144
block output operations= 51352
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 125
involuntary context switches= 1636

runsolver used 0.032002 second user time and 0.044002 second system time

The end