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/upgrade/difficult/rand752.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/upgrade/difficult/rand752.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/upgrade/difficult/rand752.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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.86 0.97 0.95 2/56 28123
/proc/meminfo: memFree=396792/1022884 swapFree=0/0
[pid=28123] ppid=28122 vsize=9204 CPUtime=0
/proc/28123/stat : 28123 (aspuncud-full) S 28122 28123 32685 0 -1 4202496 431 0 0 0 0 0 0 0 20 0 1 0 42445890 9424896 332 18446744073709551615 4194304 5129932 140733411510176 140733411507640 140573716834080 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/28123/statm: 2301 332 272 229 0 61 0

[startup+0.193607 s]
/proc/loadavg: 0.86 0.97 0.95 2/56 28123
/proc/meminfo: memFree=396792/1022884 swapFree=0/0
[pid=28123] ppid=28122 vsize=9212 CPUtime=0.03
/proc/28123/stat : 28123 (aspuncud-full) S 28122 28123 32685 0 -1 4202496 699 2806 0 0 0 0 2 1 20 0 1 0 42445890 9433088 365 18446744073709551615 4194304 5129932 140733411510176 140733411508832 140573716690014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/28123/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200321 s]
/proc/loadavg: 0.86 0.97 0.95 2/56 28123
/proc/meminfo: memFree=396792/1022884 swapFree=0/0
[pid=28123] ppid=28122 vsize=9212 CPUtime=0.03
/proc/28123/stat : 28123 (aspuncud-full) S 28122 28123 32685 0 -1 4202496 699 2806 0 0 0 0 2 1 20 0 1 0 42445890 9433088 365 18446744073709551615 4194304 5129932 140733411510176 140733411508832 140573716690014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/28123/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300345 s]
/proc/loadavg: 0.86 0.97 0.95 2/56 28123
/proc/meminfo: memFree=396792/1022884 swapFree=0/0
[pid=28123] ppid=28122 vsize=9212 CPUtime=0.03
/proc/28123/stat : 28123 (aspuncud-full) S 28122 28123 32685 0 -1 4202496 699 2806 0 0 0 0 2 1 20 0 1 0 42445890 9433088 365 18446744073709551615 4194304 5129932 140733411510176 140733411508832 140573716690014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/28123/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.70022 s]
/proc/loadavg: 0.86 0.97 0.95 2/56 28123
/proc/meminfo: memFree=396792/1022884 swapFree=0/0
[pid=28123] ppid=28122 vsize=9212 CPUtime=0.03
/proc/28123/stat : 28123 (aspuncud-full) S 28122 28123 32685 0 -1 4202496 699 2806 0 0 0 0 2 1 20 0 1 0 42445890 9433088 365 18446744073709551615 4194304 5129932 140733411510176 140733411508832 140573716690014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/28123/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 0.87 0.97 0.95 2/58 28136
/proc/meminfo: memFree=362040/1022884 swapFree=0/0
[pid=28123] ppid=28122 vsize=9212 CPUtime=0.03
/proc/28123/stat : 28123 (aspuncud-full) S 28122 28123 32685 0 -1 4202496 699 2806 0 0 0 0 2 1 20 0 1 0 42445890 9433088 365 18446744073709551615 4194304 5129932 140733411510176 140733411508832 140573716690014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/28123/statm: 2303 365 303 229 0 63 0
[pid=28136] ppid=28123 vsize=57072 CPUtime=1.44
/proc/28136/stat : 28136 (cudf2lp) R 28123 28123 32685 0 -1 4202496 14014 0 0 0 140 4 0 0 20 0 1 0 42445892 58441728 12279 18446744073709551615 4194304 5690517 140735684678416 140735684674584 4363479 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/28136/statm: 14268 12279 160 366 0 13899 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 66284

[startup+3.10032 s]
/proc/loadavg: 0.87 0.97 0.95 2/58 28136
/proc/meminfo: memFree=330048/1022884 swapFree=0/0
[pid=28123] ppid=28122 vsize=9212 CPUtime=0.03
/proc/28123/stat : 28123 (aspuncud-full) S 28122 28123 32685 0 -1 4202496 699 2806 0 0 0 0 2 1 20 0 1 0 42445890 9433088 365 18446744073709551615 4194304 5129932 140733411510176 140733411508832 140573716690014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/28123/statm: 2303 365 303 229 0 63 0
[pid=28136] ppid=28123 vsize=93028 CPUtime=3.02
/proc/28136/stat : 28136 (cudf2lp) R 28123 28123 32685 0 -1 4202496 26549 0 0 0 291 11 0 0 20 0 1 0 42445892 95260672 19820 18446744073709551615 4194304 5690517 140735684678416 140735684676056 4960643 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/28136/statm: 23257 19820 160 366 0 22888 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 102240

[startup+6.3003 s]
/proc/loadavg: 0.88 0.97 0.95 2/58 28137
/proc/meminfo: memFree=338604/1022884 swapFree=0/0
[pid=28123] ppid=28122 vsize=9212 CPUtime=4.95
/proc/28123/stat : 28123 (aspuncud-full) S 28122 28123 32685 0 -1 4202496 726 42129 0 0 0 0 468 27 20 0 1 0 42445890 9433088 365 18446744073709551615 4194304 5129932 140733411510176 140733411508832 140573716690014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/28123/statm: 2303 365 303 229 0 63 0
[pid=28137] ppid=28123 vsize=39828 CPUtime=1.26
/proc/28137/stat : 28137 (gringo) R 28123 28123 32685 0 -1 4202496 11089 0 0 0 122 4 0 0 20 0 1 0 42446392 40783872 7955 18446744073709551615 4194304 6531320 140735956467136 140735956462952 4341012 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/28137/statm: 9957 7955 259 571 0 9378 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 49040

[startup+12.7003 s]
/proc/loadavg: 0.89 0.97 0.95 2/58 28137
/proc/meminfo: memFree=10208/1022884 swapFree=0/0
[pid=28123] ppid=28122 vsize=9212 CPUtime=4.95
/proc/28123/stat : 28123 (aspuncud-full) S 28122 28123 32685 0 -1 4202496 726 42129 0 0 0 0 468 27 20 0 1 0 42445890 9433088 365 18446744073709551615 4194304 5129932 140733411510176 140733411508832 140573716690014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/28123/statm: 2303 365 303 229 0 63 0
[pid=28137] ppid=28123 vsize=461644 CPUtime=7.47
/proc/28137/stat : 28137 (gringo) R 28123 28123 32685 0 -1 4202496 110447 0 0 0 694 53 0 0 20 0 1 0 42446392 472723456 100516 18446744073709551615 4194304 6531320 140735956467136 140735956464808 4344251 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/28137/statm: 115411 100516 284 571 0 114832 0
Current children cumulated CPU time (s) 12.42
Current children cumulated vsize (KiB) 470856

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

[startup+12.8004 s]
/proc/loadavg: 0.89 0.97 0.95 2/58 28137
/proc/meminfo: memFree=10208/1022884 swapFree=0/0
[pid=28123] ppid=28122 vsize=9212 CPUtime=4.95
/proc/28123/stat : 28123 (aspuncud-full) S 28122 28123 32685 0 -1 4202496 726 42129 0 0 0 0 468 27 20 0 1 0 42445890 9433088 365 18446744073709551615 4194304 5129932 140733411510176 140733411508832 140573716690014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/28123/statm: 2303 365 303 229 0 63 0
[pid=28137] ppid=28123 vsize=428872 CPUtime=7.57
/proc/28137/stat : 28137 (gringo) R 28123 28123 32685 0 -1 4202496 110447 0 0 0 703 54 0 0 20 0 1 0 42446392 439164928 92969 18446744073709551615 4194304 6531320 140735956467136 140735956464824 4318249 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/28137/statm: 107218 92969 284 571 0 106639 0
Current children cumulated CPU time (s) 12.52
Current children cumulated vsize (KiB) 438084

[startup+14.4085 s]
/proc/loadavg: 0.89 0.97 0.95 2/59 28139
/proc/meminfo: memFree=266800/1022884 swapFree=0/0
[pid=28123] ppid=28122 vsize=9212 CPUtime=12.8
/proc/28123/stat : 28123 (aspuncud-full) S 28122 28123 32685 0 -1 4202496 767 152580 0 0 0 0 1185 95 20 0 1 0 42445890 9433088 365 18446744073709551615 4194304 5129932 140733411510176 140733411508240 140573716690014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/28123/statm: 2303 365 303 229 0 63 0
[pid=28138] ppid=28123 vsize=139076 CPUtime=1.27
/proc/28138/stat : 28138 (unclasp) R 28123 28123 32685 0 -1 4202496 40436 0 1 0 116 11 0 0 20 0 1 0 42447197 142413824 34266 18446744073709551615 4194304 6012874 140733378570064 140733378569240 5251026 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/28138/statm: 34769 34266 218 444 0 34317 0
[pid=28139] ppid=28123 vsize=22040 CPUtime=0.02
/proc/28139/stat : 28139 (parse.py) S 28123 28123 32685 0 -1 4202496 1310 0 10 0 1 1 0 0 20 0 1 0 42447197 22568960 1128 18446744073709551615 4194304 6642060 140734249733072 140734249731432 139790965536544 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/28139/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 14.09
Current children cumulated vsize (KiB) 170328

[startup+15.2004 s]
/proc/loadavg: 0.89 0.97 0.95 2/59 28139
/proc/meminfo: memFree=266800/1022884 swapFree=0/0
[pid=28123] ppid=28122 vsize=9212 CPUtime=12.8
/proc/28123/stat : 28123 (aspuncud-full) S 28122 28123 32685 0 -1 4202496 767 152580 0 0 0 0 1185 95 20 0 1 0 42445890 9433088 365 18446744073709551615 4194304 5129932 140733411510176 140733411508240 140573716690014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/28123/statm: 2303 365 303 229 0 63 0
[pid=28138] ppid=28123 vsize=139076 CPUtime=2.06
/proc/28138/stat : 28138 (unclasp) R 28123 28123 32685 0 -1 4202496 40446 0 1 0 195 11 0 0 20 0 1 0 42447197 142413824 34276 18446744073709551615 4194304 6012874 140733378570064 140733378569384 4548906 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/28138/statm: 34769 34276 226 444 0 34317 0
[pid=28139] ppid=28123 vsize=22044 CPUtime=0.02
/proc/28139/stat : 28139 (parse.py) S 28123 28123 32685 0 -1 4202496 1314 0 10 0 1 1 0 0 20 0 1 0 42447197 22573056 1132 18446744073709551615 4194304 6642060 140734249733072 140734249731272 139790965536544 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/28139/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 14.88
Current children cumulated vsize (KiB) 170332

[startup+15.6004 s]
/proc/loadavg: 0.89 0.97 0.95 2/59 28139
/proc/meminfo: memFree=273868/1022884 swapFree=0/0
[pid=28123] ppid=28122 vsize=9212 CPUtime=15.22
/proc/28123/stat : 28123 (aspuncud-full) S 28122 28123 32685 0 -1 4202496 801 194384 0 11 0 0 1408 114 20 0 1 0 42445890 9433088 365 18446744073709551615 4194304 5129932 140733411510176 140733411507728 140573716690014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/28123/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 15.22
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 15.6222
CPU time (s): 15.249
CPU user time (s): 14.0929
CPU system time (s): 1.15607
CPU usage (%): 97.6107
Max. virtual memory (cumulated for all children) (KiB): 474956

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 14.0929
system time used= 1.15607
maximum resident set size= 404668
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 195417
page faults= 12
swaps= 0
block input operations= 69688
block output operations= 51200
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 231
involuntary context switches= 382

runsolver used 0.016001 second user time and 0.088005 second system time

The end