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/real/8222799a-9af8-11df-8b50-00163e46d37a.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/real/8222799a-9af8-11df-8b50-00163e46d37a.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/paranoid-size/real/8222799a-9af8-11df-8b50-00163e46d37a.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.02 1.01 0.91 2/60 21527
/proc/meminfo: memFree=387952/1022884 swapFree=0/0
[pid=21527] ppid=21526 vsize=9204 CPUtime=0
/proc/21527/stat : 21527 (aspuncud-basic) S 21526 21527 1733 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 115377674 9424896 332 18446744073709551615 4194304 5129932 140736641120672 140736641118136 140210279741216 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/21527/statm: 2301 332 272 229 0 61 0

[startup+0.173112 s]
/proc/loadavg: 1.02 1.01 0.91 2/60 21527
/proc/meminfo: memFree=387952/1022884 swapFree=0/0
[pid=21527] ppid=21526 vsize=9212 CPUtime=0.02
/proc/21527/stat : 21527 (aspuncud-basic) S 21526 21527 1733 0 -1 4202496 698 2811 0 0 0 0 2 0 20 0 1 0 115377674 9433088 365 18446744073709551615 4194304 5129932 140736641120672 140736641119328 140210279597150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21527/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200299 s]
/proc/loadavg: 1.02 1.01 0.91 2/60 21527
/proc/meminfo: memFree=387952/1022884 swapFree=0/0
[pid=21527] ppid=21526 vsize=9212 CPUtime=0.02
/proc/21527/stat : 21527 (aspuncud-basic) S 21526 21527 1733 0 -1 4202496 698 2811 0 0 0 0 2 0 20 0 1 0 115377674 9433088 365 18446744073709551615 4194304 5129932 140736641120672 140736641119328 140210279597150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21527/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300268 s]
/proc/loadavg: 1.02 1.01 0.91 2/60 21527
/proc/meminfo: memFree=387952/1022884 swapFree=0/0
[pid=21527] ppid=21526 vsize=9212 CPUtime=0.02
/proc/21527/stat : 21527 (aspuncud-basic) S 21526 21527 1733 0 -1 4202496 698 2811 0 0 0 0 2 0 20 0 1 0 115377674 9433088 365 18446744073709551615 4194304 5129932 140736641120672 140736641119328 140210279597150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21527/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700223 s]
/proc/loadavg: 1.02 1.01 0.91 2/60 21527
/proc/meminfo: memFree=387952/1022884 swapFree=0/0
[pid=21527] ppid=21526 vsize=9212 CPUtime=0.02
/proc/21527/stat : 21527 (aspuncud-basic) S 21526 21527 1733 0 -1 4202496 698 2811 0 0 0 0 2 0 20 0 1 0 115377674 9433088 365 18446744073709551615 4194304 5129932 140736641120672 140736641119328 140210279597150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21527/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.02 1.01 0.91 2/62 21540
/proc/meminfo: memFree=330640/1022884 swapFree=0/0
[pid=21527] ppid=21526 vsize=9212 CPUtime=0.02
/proc/21527/stat : 21527 (aspuncud-basic) S 21526 21527 1733 0 -1 4202496 698 2811 0 0 0 0 2 0 20 0 1 0 115377674 9433088 365 18446744073709551615 4194304 5129932 140736641120672 140736641119328 140210279597150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21527/statm: 2303 365 303 229 0 63 0
[pid=21540] ppid=21527 vsize=75480 CPUtime=1.41
/proc/21540/stat : 21540 (cudf2lp) R 21527 21527 1733 0 -1 4202496 21061 0 0 0 134 7 0 0 20 0 1 0 115377676 77291520 17661 18446744073709551615 4194304 5690517 140733928665872 140733928663000 4272019 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/21540/statm: 18870 17661 168 366 0 18501 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 84692

[startup+3.10031 s]
/proc/loadavg: 1.02 1.01 0.91 2/62 21541
/proc/meminfo: memFree=346140/1022884 swapFree=0/0
[pid=21527] ppid=21526 vsize=9212 CPUtime=1.74
/proc/21527/stat : 21527 (aspuncud-basic) S 21526 21527 1733 0 -1 4202496 725 25388 0 0 0 0 164 10 20 0 1 0 115377674 9433088 365 18446744073709551615 4194304 5129932 140736641120672 140736641119328 140210279597150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21527/statm: 2303 365 303 229 0 63 0
[pid=21541] ppid=21527 vsize=97168 CPUtime=1.29
/proc/21541/stat : 21541 (gringo) R 21527 21527 1733 0 -1 4202496 23906 0 0 0 122 7 0 0 20 0 1 0 115377853 99500032 21286 18446744073709551615 4194304 6531320 140734736566944 140734736563928 4585835 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21541/statm: 24292 21286 282 571 0 23713 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 106380

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

[startup+3.20039 s]
/proc/loadavg: 1.02 1.01 0.91 2/62 21541
/proc/meminfo: memFree=346140/1022884 swapFree=0/0
[pid=21527] ppid=21526 vsize=9212 CPUtime=1.74
/proc/21527/stat : 21527 (aspuncud-basic) S 21526 21527 1733 0 -1 4202496 725 25388 0 0 0 0 164 10 20 0 1 0 115377674 9433088 365 18446744073709551615 4194304 5129932 140736641120672 140736641119328 140210279597150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21527/statm: 2303 365 303 229 0 63 0
[pid=21541] ppid=21527 vsize=104408 CPUtime=1.39
/proc/21541/stat : 21541 (gringo) R 21527 21527 1733 0 -1 4202496 25672 0 0 0 131 8 0 0 20 0 1 0 115377853 106913792 23052 18446744073709551615 4194304 6531320 140734736566944 140734736563560 4359041 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21541/statm: 26102 23052 282 571 0 25523 0
Current children cumulated CPU time (s) 3.13
Current children cumulated vsize (KiB) 113620

[startup+4.00026 s]
/proc/loadavg: 1.02 1.01 0.91 2/62 21541
/proc/meminfo: memFree=256364/1022884 swapFree=0/0
[pid=21527] ppid=21526 vsize=9212 CPUtime=3.84
/proc/21527/stat : 21527 (aspuncud-basic) S 21526 21527 1733 0 -1 4202496 765 65322 0 0 0 0 355 29 20 0 1 0 115377674 9433088 365 18446744073709551615 4194304 5129932 140736641120672 140736641118736 140210279597150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21527/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 3.84
Current children cumulated vsize (KiB) 9212

[startup+4.40021 s]
/proc/loadavg: 1.02 1.01 0.91 2/63 21543
/proc/meminfo: memFree=311536/1022884 swapFree=0/0
[pid=21527] ppid=21526 vsize=9212 CPUtime=3.84
/proc/21527/stat : 21527 (aspuncud-basic) S 21526 21527 1733 0 -1 4202496 765 65322 0 0 0 0 355 29 20 0 1 0 115377674 9433088 365 18446744073709551615 4194304 5129932 140736641120672 140736641118736 140210279597150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21527/statm: 2303 365 303 229 0 63 0
[pid=21542] ppid=21527 vsize=45952 CPUtime=0.46
/proc/21542/stat : 21542 (unclasp) R 21527 21527 1733 0 -1 4202496 13740 0 0 0 42 4 0 0 20 0 1 0 115378066 47054848 11184 18446744073709551615 4194304 6012874 140736799859744 140736799859064 4548198 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21542/statm: 11488 11184 226 444 0 11036 0
[pid=21543] ppid=21527 vsize=22188 CPUtime=0.01
/proc/21543/stat : 21543 (parse.py) S 21527 21527 1733 0 -1 4202496 1341 0 0 0 0 1 0 0 20 0 1 0 115378066 22720512 1151 18446744073709551615 4194304 6642060 140736668923472 140736668921720 140459414652704 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21543/statm: 5547 1151 508 598 0 633 0
Current children cumulated CPU time (s) 4.31
Current children cumulated vsize (KiB) 77352

[startup+4.60238 s]
/proc/loadavg: 1.02 1.01 0.91 2/63 21543
/proc/meminfo: memFree=311536/1022884 swapFree=0/0
[pid=21527] ppid=21526 vsize=9212 CPUtime=3.84
/proc/21527/stat : 21527 (aspuncud-basic) S 21526 21527 1733 0 -1 4202496 765 65322 0 0 0 0 355 29 20 0 1 0 115377674 9433088 365 18446744073709551615 4194304 5129932 140736641120672 140736641118736 140210279597150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21527/statm: 2303 365 303 229 0 63 0
[pid=21542] ppid=21527 vsize=0 CPUtime=0.65
/proc/21542/stat : 21542 (unclasp) R 21527 21527 1733 0 -1 4202500 13750 0 0 0 60 5 0 0 20 0 1 0 115378066 0 0 18446744073709551615 0 0 0 0 0 0 0 16781316 16386 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21542/statm: 0 0 0 0 0 0 0
[pid=21543] ppid=21527 vsize=22188 CPUtime=0.01
/proc/21543/stat : 21543 (parse.py) R 21527 21527 1733 0 -1 4202496 1355 0 0 0 0 1 0 0 20 0 1 0 115378066 22720512 1163 18446744073709551615 4194304 6642060 140736668923472 140736668922376 4989859 0 0 16777220 0 0 0 0 17 0 0 0 0 0 0
/proc/21543/statm: 5547 1163 520 598 0 633 0
Current children cumulated CPU time (s) 4.5
Current children cumulated vsize (KiB) 31400

Child status: 0
Real time (s): 4.60917
CPU time (s): 4.54028
CPU user time (s): 4.17626
CPU system time (s): 0.364022
CPU usage (%): 98.5054
Max. virtual memory (cumulated for all children) (KiB): 174340

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.17626
system time used= 0.364022
maximum resident set size= 141044
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 81463
page faults= 0
swaps= 0
block input operations= 37864
block output operations= 19704
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 88
involuntary context switches= 563

runsolver used 0.004 second user time and 0.028001 second system time

The end