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/rand7.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/install/rand7.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/install/rand7.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.96 0.99 0.99 2/64 20718
/proc/meminfo: memFree=459856/1022884 swapFree=0/0
[pid=20718] ppid=20717 vsize=3152 CPUtime=0
/proc/20718/stat : 20718 (runsolver) R 20717 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120592862 3227648 33 18446744073709551615 134512640 134586868 4288230320 4288228368 4152108080 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/20718/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.137099 s]
/proc/loadavg: 0.96 0.99 0.99 2/64 20718
/proc/meminfo: memFree=459856/1022884 swapFree=0/0
[pid=20718] ppid=20717 vsize=9212 CPUtime=0.04
/proc/20718/stat : 20718 (aspuncud-full) S 20717 20718 1745 0 -1 4202496 696 2809 0 0 0 0 4 0 20 0 1 0 120592862 9433088 364 18446744073709551615 4194304 5129932 140734985469616 140734985468272 139865391916126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20718/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.20034 s]
/proc/loadavg: 0.96 0.99 0.99 2/64 20718
/proc/meminfo: memFree=459856/1022884 swapFree=0/0
[pid=20718] ppid=20717 vsize=9212 CPUtime=0.04
/proc/20718/stat : 20718 (aspuncud-full) S 20717 20718 1745 0 -1 4202496 696 2809 0 0 0 0 4 0 20 0 1 0 120592862 9433088 364 18446744073709551615 4194304 5129932 140734985469616 140734985468272 139865391916126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20718/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300315 s]
/proc/loadavg: 0.96 0.99 0.99 2/64 20718
/proc/meminfo: memFree=459856/1022884 swapFree=0/0
[pid=20718] ppid=20717 vsize=9212 CPUtime=0.04
/proc/20718/stat : 20718 (aspuncud-full) S 20717 20718 1745 0 -1 4202496 696 2809 0 0 0 0 4 0 20 0 1 0 120592862 9433088 364 18446744073709551615 4194304 5129932 140734985469616 140734985468272 139865391916126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20718/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700229 s]
/proc/loadavg: 0.96 0.99 0.99 2/64 20718
/proc/meminfo: memFree=459856/1022884 swapFree=0/0
[pid=20718] ppid=20717 vsize=9212 CPUtime=0.04
/proc/20718/stat : 20718 (aspuncud-full) S 20717 20718 1745 0 -1 4202496 696 2809 0 0 0 0 4 0 20 0 1 0 120592862 9433088 364 18446744073709551615 4194304 5129932 140734985469616 140734985468272 139865391916126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20718/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.97 0.99 0.99 2/66 20731
/proc/meminfo: memFree=425360/1022884 swapFree=0/0
[pid=20718] ppid=20717 vsize=9212 CPUtime=0.04
/proc/20718/stat : 20718 (aspuncud-full) S 20717 20718 1745 0 -1 4202496 696 2809 0 0 0 0 4 0 20 0 1 0 120592862 9433088 364 18446744073709551615 4194304 5129932 140734985469616 140734985468272 139865391916126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20718/statm: 2303 364 303 229 0 63 0
[pid=20731] ppid=20718 vsize=47172 CPUtime=1.42
/proc/20731/stat : 20731 (cudf2lp) R 20718 20718 1745 0 -1 4202496 10195 0 1 0 136 6 0 0 20 0 1 0 120592865 48304128 8463 18446744073709551615 4194304 5690517 140736105431968 140736105428136 4363476 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/20731/statm: 11793 8463 160 366 0 11424 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 56384

[startup+3.10033 s]
/proc/loadavg: 0.97 0.99 0.99 2/66 20731
/proc/meminfo: memFree=393740/1022884 swapFree=0/0
[pid=20718] ppid=20717 vsize=9212 CPUtime=0.04
/proc/20718/stat : 20718 (aspuncud-full) S 20717 20718 1745 0 -1 4202496 696 2809 0 0 0 0 4 0 20 0 1 0 120592862 9433088 364 18446744073709551615 4194304 5129932 140734985469616 140734985468272 139865391916126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20718/statm: 2303 364 303 229 0 63 0
[pid=20731] ppid=20718 vsize=93028 CPUtime=3.01
/proc/20731/stat : 20731 (cudf2lp) R 20718 20718 1745 0 -1 4202496 26472 0 1 0 288 13 0 0 20 0 1 0 120592865 95260672 19746 18446744073709551615 4194304 5690517 140736105431968 140736105429608 4811648 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/20731/statm: 23257 19746 160 366 0 22888 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 102240

[startup+6.30033 s]
/proc/loadavg: 0.97 0.99 0.99 2/66 20732
/proc/meminfo: memFree=403412/1022884 swapFree=0/0
[pid=20718] ppid=20717 vsize=9212 CPUtime=5.04
/proc/20718/stat : 20718 (aspuncud-full) S 20717 20718 1745 0 -1 4202496 724 42128 0 1 0 1 476 27 20 0 1 0 120592862 9433088 364 18446744073709551615 4194304 5129932 140734985469616 140734985468272 139865391916126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20718/statm: 2303 364 303 229 0 63 0
[pid=20732] ppid=20718 vsize=32880 CPUtime=1.18
/proc/20732/stat : 20732 (gringo) R 20718 20718 1745 0 -1 4202496 9377 0 0 0 113 5 0 0 20 0 1 0 120593372 33669120 7269 18446744073709551615 4194304 6531320 140735240007680 140735240004296 5188251 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20732/statm: 8220 7269 259 571 0 7641 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 42092

[startup+12.7003 s]
/proc/loadavg: 0.97 0.99 0.99 2/66 20732
/proc/meminfo: memFree=24592/1022884 swapFree=0/0
[pid=20718] ppid=20717 vsize=9212 CPUtime=5.04
/proc/20718/stat : 20718 (aspuncud-full) S 20717 20718 1745 0 -1 4202496 724 42128 0 1 0 1 476 27 20 0 1 0 120592862 9433088 364 18446744073709551615 4194304 5129932 140734985469616 140734985468272 139865391916126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20718/statm: 2303 364 303 229 0 63 0
[pid=20732] ppid=20718 vsize=478976 CPUtime=7.44
/proc/20732/stat : 20732 (gringo) R 20718 20718 1745 0 -1 4202496 113596 0 0 0 698 46 0 0 20 0 1 0 120593372 490471424 104317 18446744073709551615 4194304 6531320 140735240007680 140735240004440 4600146 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20732/statm: 119744 104317 284 571 0 119165 0
Current children cumulated CPU time (s) 12.48
Current children cumulated vsize (KiB) 488188

[startup+25.5004 s]
/proc/loadavg: 0.98 0.99 0.99 2/67 20734
/proc/meminfo: memFree=284240/1022884 swapFree=0/0
[pid=20718] ppid=20717 vsize=9212 CPUtime=13.17
/proc/20718/stat : 20718 (aspuncud-full) S 20717 20718 1745 0 -1 4202496 765 155728 0 1 0 1 1228 88 20 0 1 0 120592862 9433088 364 18446744073709551615 4194304 5129932 140734985469616 140734985467680 139865391916126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20718/statm: 2303 364 303 229 0 63 0
[pid=20733] ppid=20718 vsize=142712 CPUtime=11.96
/proc/20733/stat : 20733 (unclasp) R 20718 20718 1745 0 -1 4202496 41403 0 0 0 1180 16 0 0 20 0 1 0 120594200 146137088 35179 18446744073709551615 4194304 6012874 140735336186576 140735336185896 4548105 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20733/statm: 35678 35179 226 444 0 35226 0
[pid=20734] ppid=20718 vsize=22044 CPUtime=0.01
/proc/20734/stat : 20734 (parse.py) S 20718 20718 1745 0 -1 4202496 1322 0 0 0 0 1 0 0 20 0 1 0 120594200 22573056 1131 18446744073709551615 4194304 6642060 140736948947744 140736948945992 140277993133856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20734/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 25.14
Current children cumulated vsize (KiB) 173968

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

[startup+25.6006 s]
/proc/loadavg: 0.98 0.99 0.99 2/67 20734
/proc/meminfo: memFree=284240/1022884 swapFree=0/0
[pid=20718] ppid=20717 vsize=9212 CPUtime=13.17
/proc/20718/stat : 20718 (aspuncud-full) S 20717 20718 1745 0 -1 4202496 765 155728 0 1 0 1 1228 88 20 0 1 0 120592862 9433088 364 18446744073709551615 4194304 5129932 140734985469616 140734985467680 139865391916126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20718/statm: 2303 364 303 229 0 63 0
[pid=20733] ppid=20718 vsize=142712 CPUtime=12.05
/proc/20733/stat : 20733 (unclasp) R 20718 20718 1745 0 -1 4202496 41403 0 0 0 1189 16 0 0 20 0 1 0 120594200 146137088 35179 18446744073709551615 4194304 6012874 140735336186576 140735336185896 4568761 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20733/statm: 35678 35179 226 444 0 35226 0
[pid=20734] ppid=20718 vsize=22044 CPUtime=0.01
/proc/20734/stat : 20734 (parse.py) S 20718 20718 1745 0 -1 4202496 1322 0 0 0 0 1 0 0 20 0 1 0 120594200 22573056 1131 18446744073709551615 4194304 6642060 140736948947744 140736948945992 140277993133856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20734/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 25.23
Current children cumulated vsize (KiB) 173968

[startup+26.0005 s]
/proc/loadavg: 0.98 0.99 0.99 2/67 20734
/proc/meminfo: memFree=284240/1022884 swapFree=0/0
[pid=20718] ppid=20717 vsize=9212 CPUtime=13.17
/proc/20718/stat : 20718 (aspuncud-full) S 20717 20718 1745 0 -1 4202496 765 155728 0 1 0 1 1228 88 20 0 1 0 120592862 9433088 364 18446744073709551615 4194304 5129932 140734985469616 140734985467680 139865391916126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20718/statm: 2303 364 303 229 0 63 0
[pid=20733] ppid=20718 vsize=142712 CPUtime=12.46
/proc/20733/stat : 20733 (unclasp) R 20718 20718 1745 0 -1 4202496 41411 0 0 0 1226 20 0 0 20 0 1 0 120594200 146137088 12659 18446744073709551615 4194304 6012874 140735336186576 140735336185976 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20733/statm: 35678 12659 234 444 0 35226 0
[pid=20734] ppid=20718 vsize=22176 CPUtime=0.02
/proc/20734/stat : 20734 (parse.py) S 20718 20718 1745 0 -1 4202496 1335 0 0 0 1 1 0 0 20 0 1 0 120594200 22708224 1144 18446744073709551615 4194304 6642060 140736948947744 140736948946024 140277993133856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20734/statm: 5544 1144 508 598 0 630 0
Current children cumulated CPU time (s) 25.65
Current children cumulated vsize (KiB) 174100

Child status: 0
Real time (s): 26.0352
CPU time (s): 25.7096
CPU user time (s): 24.5695
CPU system time (s): 1.14007
CPU usage (%): 98.7495
Max. virtual memory (cumulated for all children) (KiB): 488188

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 24.5695
system time used= 1.14007
maximum resident set size= 417268
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 199525
page faults= 1
swaps= 0
block input operations= 68552
block output operations= 52336
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 98
involuntary context switches= 3037

runsolver used 0.064004 second user time and 0.132008 second system time

The end