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 150 -d 10 -w /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/paranoid-size/install/rand30.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/install/rand30.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/paranoid-size/install/rand30.cudf.result -count(removed),-sum(solution,installedsize),-count(changed) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 150 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 180 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.01 0.97 0.87 2/65 7379
/proc/meminfo: memFree=449764/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9204 CPUtime=0
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 37148799 9424896 332 18446744073709551615 4194304 5129932 140733824383088 140733824380552 140439938746144 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2301 332 272 229 0 61 0

[startup+0.180016 s]
/proc/loadavg: 1.01 0.97 0.87 2/65 7379
/proc/meminfo: memFree=449764/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9212 CPUtime=0.02
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 700 2806 0 0 0 0 2 0 20 0 1 0 37148799 9433088 365 18446744073709551615 4194304 5129932 140733824383088 140733824381744 140439938602078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200329 s]
/proc/loadavg: 1.01 0.97 0.87 2/65 7379
/proc/meminfo: memFree=449764/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9212 CPUtime=0.02
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 700 2806 0 0 0 0 2 0 20 0 1 0 37148799 9433088 365 18446744073709551615 4194304 5129932 140733824383088 140733824381744 140439938602078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300316 s]
/proc/loadavg: 1.01 0.97 0.87 2/65 7379
/proc/meminfo: memFree=449764/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9212 CPUtime=0.02
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 700 2806 0 0 0 0 2 0 20 0 1 0 37148799 9433088 365 18446744073709551615 4194304 5129932 140733824383088 140733824381744 140439938602078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700243 s]
/proc/loadavg: 1.01 0.97 0.87 2/65 7379
/proc/meminfo: memFree=449764/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9212 CPUtime=0.02
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 700 2806 0 0 0 0 2 0 20 0 1 0 37148799 9433088 365 18446744073709551615 4194304 5129932 140733824383088 140733824381744 140439938602078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50026 s]
/proc/loadavg: 1.01 0.97 0.87 1/67 7392
/proc/meminfo: memFree=415020/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9212 CPUtime=0.02
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 700 2806 0 0 0 0 2 0 20 0 1 0 37148799 9433088 365 18446744073709551615 4194304 5129932 140733824383088 140733824381744 140439938602078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2303 365 303 229 0 63 0
[pid=7392] ppid=7379 vsize=50676 CPUtime=1.44
/proc/7392/stat : 7392 (cudf2lp) R 7379 7379 32685 0 -1 4202496 14351 0 0 0 138 6 0 0 20 0 1 0 37148801 51892224 10952 18446744073709551615 4194304 5690517 140734790524240 140734790521880 4293635 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/7392/statm: 12669 10952 160 366 0 12300 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 59888

[startup+3.10025 s]
/proc/loadavg: 1.01 0.97 0.87 2/67 7392
/proc/meminfo: memFree=370132/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9212 CPUtime=0.02
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 700 2806 0 0 0 0 2 0 20 0 1 0 37148799 9433088 365 18446744073709551615 4194304 5129932 140733824383088 140733824381744 140439938602078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2303 365 303 229 0 63 0
[pid=7392] ppid=7379 vsize=135316 CPUtime=3.02
/proc/7392/stat : 7392 (cudf2lp) R 7379 7379 32685 0 -1 4202496 37802 0 0 0 288 14 0 0 20 0 1 0 37148801 138563584 31074 18446744073709551615 4194304 5690517 140734790524240 140734790521368 4271598 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/7392/statm: 33829 31074 168 366 0 33460 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 144528

[startup+6.30025 s]
/proc/loadavg: 1.01 0.97 0.88 2/67 7393
/proc/meminfo: memFree=285192/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9212 CPUtime=3.63
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 728 42127 0 0 0 0 344 19 20 0 1 0 37148799 9433088 365 18446744073709551615 4194304 5129932 140733824383088 140733824381744 140439938602078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2303 365 303 229 0 63 0
[pid=7393] ppid=7379 vsize=208532 CPUtime=2.6
/proc/7393/stat : 7393 (gringo) R 7379 7379 32685 0 -1 4202496 52468 0 0 0 243 17 0 0 20 0 1 0 37149167 213536768 43187 18446744073709551615 4194304 6531320 140736619791744 140736619788360 4359104 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/7393/statm: 52133 43187 283 571 0 51554 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 217744

[startup+12.7003 s]
/proc/loadavg: 1.01 0.97 0.88 2/68 7395
/proc/meminfo: memFree=270428/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9212 CPUtime=8.49
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 771 150316 0 0 0 0 784 65 20 0 1 0 37148799 9433088 365 18446744073709551615 4194304 5129932 140733824383088 140733824381152 140439938602078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2303 365 303 229 0 63 0
[pid=7394] ppid=7379 vsize=135312 CPUtime=4.06
/proc/7394/stat : 7394 (unclasp) R 7379 7379 32685 0 -1 4202496 39343 0 0 0 396 10 0 0 20 0 1 0 37149658 138559488 33244 18446744073709551615 4194304 6012874 140734814670688 140734814670008 4548507 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/7394/statm: 33828 33244 226 444 0 33376 0
[pid=7395] ppid=7379 vsize=22360 CPUtime=0.01
/proc/7395/stat : 7395 (parse.py) S 7379 7379 32685 0 -1 4202496 1371 0 0 0 0 1 0 0 20 0 1 0 37149658 22896640 1180 18446744073709551615 4194304 6642060 140736356057888 140736356056008 140084845983520 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/7395/statm: 5590 1180 508 598 0 676 0
Current children cumulated CPU time (s) 12.56
Current children cumulated vsize (KiB) 166884

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

[startup+12.8004 s]
/proc/loadavg: 1.01 0.97 0.88 2/68 7395
/proc/meminfo: memFree=270428/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9212 CPUtime=8.49
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 771 150316 0 0 0 0 784 65 20 0 1 0 37148799 9433088 365 18446744073709551615 4194304 5129932 140733824383088 140733824381152 140439938602078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2303 365 303 229 0 63 0
[pid=7394] ppid=7379 vsize=135312 CPUtime=4.16
/proc/7394/stat : 7394 (unclasp) R 7379 7379 32685 0 -1 4202496 39343 0 0 0 406 10 0 0 20 0 1 0 37149658 138559488 33244 18446744073709551615 4194304 6012874 140734814670688 140734814670008 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/7394/statm: 33828 33244 226 444 0 33376 0
[pid=7395] ppid=7379 vsize=22360 CPUtime=0.01
/proc/7395/stat : 7395 (parse.py) S 7379 7379 32685 0 -1 4202496 1371 0 0 0 0 1 0 0 20 0 1 0 37149658 22896640 1180 18446744073709551615 4194304 6642060 140736356057888 140736356056008 140084845983520 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/7395/statm: 5590 1180 508 598 0 676 0
Current children cumulated CPU time (s) 12.66
Current children cumulated vsize (KiB) 166884

[startup+14.4077 s]
/proc/loadavg: 1.00 0.97 0.88 2/68 7395
/proc/meminfo: memFree=270428/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9212 CPUtime=8.49
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 771 150316 0 0 0 0 784 65 20 0 1 0 37148799 9433088 365 18446744073709551615 4194304 5129932 140733824383088 140733824381152 140439938602078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2303 365 303 229 0 63 0
[pid=7394] ppid=7379 vsize=135312 CPUtime=5.75
/proc/7394/stat : 7394 (unclasp) R 7379 7379 32685 0 -1 4202496 39343 0 0 0 564 11 0 0 20 0 1 0 37149658 138559488 33244 18446744073709551615 4194304 6012874 140734814670688 140734814670008 4548507 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/7394/statm: 33828 33244 226 444 0 33376 0
[pid=7395] ppid=7379 vsize=22360 CPUtime=0.01
/proc/7395/stat : 7395 (parse.py) S 7379 7379 32685 0 -1 4202496 1371 0 0 0 0 1 0 0 20 0 1 0 37149658 22896640 1180 18446744073709551615 4194304 6642060 140736356057888 140736356056008 140084845983520 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/7395/statm: 5590 1180 508 598 0 676 0
Current children cumulated CPU time (s) 14.25
Current children cumulated vsize (KiB) 166884

[startup+15.2003 s]
/proc/loadavg: 1.00 0.97 0.88 2/68 7395
/proc/meminfo: memFree=270428/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9212 CPUtime=8.49
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 771 150316 0 0 0 0 784 65 20 0 1 0 37148799 9433088 365 18446744073709551615 4194304 5129932 140733824383088 140733824381152 140439938602078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2303 365 303 229 0 63 0
[pid=7394] ppid=7379 vsize=135312 CPUtime=6.54
/proc/7394/stat : 7394 (unclasp) R 7379 7379 32685 0 -1 4202496 39343 0 0 0 643 11 0 0 20 0 1 0 37149658 138559488 33244 18446744073709551615 4194304 6012874 140734814670688 140734814670008 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/7394/statm: 33828 33244 226 444 0 33376 0
[pid=7395] ppid=7379 vsize=22360 CPUtime=0.01
/proc/7395/stat : 7395 (parse.py) S 7379 7379 32685 0 -1 4202496 1371 0 0 0 0 1 0 0 20 0 1 0 37149658 22896640 1180 18446744073709551615 4194304 6642060 140736356057888 140736356056008 140084845983520 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/7395/statm: 5590 1180 508 598 0 676 0
Current children cumulated CPU time (s) 15.04
Current children cumulated vsize (KiB) 166884

[startup+16.0003 s]
/proc/loadavg: 1.00 0.97 0.88 2/68 7395
/proc/meminfo: memFree=270428/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9212 CPUtime=8.49
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 771 150316 0 0 0 0 784 65 20 0 1 0 37148799 9433088 365 18446744073709551615 4194304 5129932 140733824383088 140733824381152 140439938602078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2303 365 303 229 0 63 0
[pid=7394] ppid=7379 vsize=135312 CPUtime=7.33
/proc/7394/stat : 7394 (unclasp) R 7379 7379 32685 0 -1 4202496 39343 0 0 0 722 11 0 0 20 0 1 0 37149658 138559488 33244 18446744073709551615 4194304 6012874 140734814670688 140734814670008 4307064 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/7394/statm: 33828 33244 226 444 0 33376 0
[pid=7395] ppid=7379 vsize=22360 CPUtime=0.01
/proc/7395/stat : 7395 (parse.py) S 7379 7379 32685 0 -1 4202496 1371 0 0 0 0 1 0 0 20 0 1 0 37149658 22896640 1180 18446744073709551615 4194304 6642060 140736356057888 140736356056008 140084845983520 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/7395/statm: 5590 1180 508 598 0 676 0
Current children cumulated CPU time (s) 15.83
Current children cumulated vsize (KiB) 166884

[startup+16.4003 s]
/proc/loadavg: 1.00 0.97 0.88 2/68 7395
/proc/meminfo: memFree=270428/1022884 swapFree=0/0
[pid=7379] ppid=7378 vsize=9212 CPUtime=8.49
/proc/7379/stat : 7379 (aspuncud-basic) S 7378 7379 32685 0 -1 4202496 771 150316 0 0 0 0 784 65 20 0 1 0 37148799 9433088 365 18446744073709551615 4194304 5129932 140733824383088 140733824381152 140439938602078 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/7379/statm: 2303 365 303 229 0 63 0
[pid=7394] ppid=7379 vsize=135312 CPUtime=7.73
/proc/7394/stat : 7394 (unclasp) R 7379 7379 32685 0 -1 4202496 39343 0 0 0 762 11 0 0 20 0 1 0 37149658 138559488 33244 18446744073709551615 4194304 6012874 140734814670688 140734814670008 4535764 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/7394/statm: 33828 33244 226 444 0 33376 0
[pid=7395] ppid=7379 vsize=22360 CPUtime=0.01
/proc/7395/stat : 7395 (parse.py) S 7379 7379 32685 0 -1 4202496 1371 0 0 0 0 1 0 0 20 0 1 0 37149658 22896640 1180 18446744073709551615 4194304 6642060 140736356057888 140736356056008 140084845983520 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/7395/statm: 5590 1180 508 598 0 676 0
Current children cumulated CPU time (s) 16.23
Current children cumulated vsize (KiB) 166884

Child status: 0
Real time (s): 16.4934
CPU time (s): 16.365
CPU user time (s): 15.537
CPU system time (s): 0.828051
CPU usage (%): 99.2216
Max. virtual memory (cumulated for all children) (KiB): 468836

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 15.537
system time used= 0.828051
maximum resident set size= 395616
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 192096
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 50344
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 121
involuntary context switches= 363

runsolver used 0.020001 second user time and 0.076004 second system time

The end