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/deb285a6-db9e-11df-8f4f-00163e3d3b7c.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/real/deb285a6-db9e-11df-8f4f-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/paranoid-size/real/deb285a6-db9e-11df-8f4f-00163e3d3b7c.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

[startup+0 s]
/proc/loadavg: 1.03 1.01 0.91 2/60 21505
/proc/meminfo: memFree=401716/1022884 swapFree=0/0
[pid=21505] ppid=21504 vsize=3152 CPUtime=0
/proc/21505/stat : 21505 (runsolver) R 21504 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115377024 3227648 33 18446744073709551615 134512640 134586868 4289721488 4289719536 4151645232 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/21505/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.146046 s]
/proc/loadavg: 1.03 1.01 0.91 2/60 21505
/proc/meminfo: memFree=401716/1022884 swapFree=0/0
[pid=21505] ppid=21504 vsize=9212 CPUtime=0.02
/proc/21505/stat : 21505 (aspuncud-basic) S 21504 21505 1733 0 -1 4202496 698 2813 0 0 0 0 2 0 20 0 1 0 115377024 9433088 365 18446744073709551615 4194304 5129932 140736286133152 140736286131808 140437463499870 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21505/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200265 s]
/proc/loadavg: 1.03 1.01 0.91 2/60 21505
/proc/meminfo: memFree=401716/1022884 swapFree=0/0
[pid=21505] ppid=21504 vsize=9212 CPUtime=0.02
/proc/21505/stat : 21505 (aspuncud-basic) S 21504 21505 1733 0 -1 4202496 698 2813 0 0 0 0 2 0 20 0 1 0 115377024 9433088 365 18446744073709551615 4194304 5129932 140736286133152 140736286131808 140437463499870 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21505/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.30026 s]
/proc/loadavg: 1.03 1.01 0.91 2/60 21505
/proc/meminfo: memFree=401716/1022884 swapFree=0/0
[pid=21505] ppid=21504 vsize=9212 CPUtime=0.02
/proc/21505/stat : 21505 (aspuncud-basic) S 21504 21505 1733 0 -1 4202496 698 2813 0 0 0 0 2 0 20 0 1 0 115377024 9433088 365 18446744073709551615 4194304 5129932 140736286133152 140736286131808 140437463499870 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21505/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700208 s]
/proc/loadavg: 1.03 1.01 0.91 2/60 21505
/proc/meminfo: memFree=401716/1022884 swapFree=0/0
[pid=21505] ppid=21504 vsize=9212 CPUtime=0.02
/proc/21505/stat : 21505 (aspuncud-basic) S 21504 21505 1733 0 -1 4202496 698 2813 0 0 0 0 2 0 20 0 1 0 115377024 9433088 365 18446744073709551615 4194304 5129932 140736286133152 140736286131808 140437463499870 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21505/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.5002 s]
/proc/loadavg: 1.03 1.01 0.91 2/62 21518
/proc/meminfo: memFree=337212/1022884 swapFree=0/0
[pid=21505] ppid=21504 vsize=9212 CPUtime=1.27
/proc/21505/stat : 21505 (aspuncud-basic) S 21504 21505 1733 0 -1 4202496 725 20698 0 0 0 0 118 9 20 0 1 0 115377024 9433088 365 18446744073709551615 4194304 5129932 140736286133152 140736286131808 140437463499870 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21505/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 1.27
Current children cumulated vsize (KiB) 9212

[startup+3.10063 s]
/proc/loadavg: 1.02 1.01 0.91 2/62 21519
/proc/meminfo: memFree=323944/1022884 swapFree=0/0
[pid=21505] ppid=21504 vsize=9212 CPUtime=1.27
/proc/21505/stat : 21505 (aspuncud-basic) S 21504 21505 1733 0 -1 4202496 725 20698 0 0 0 0 118 9 20 0 1 0 115377024 9433088 365 18446744073709551615 4194304 5129932 140736286133152 140736286131808 140437463499870 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21505/statm: 2303 365 303 229 0 63 0
[pid=21519] ppid=21505 vsize=183808 CPUtime=1.74
/proc/21519/stat : 21519 (gringo) R 21505 21505 1733 0 -1 4202496 44549 0 0 0 158 16 0 0 20 0 1 0 115377159 188219392 37570 18446744073709551615 4194304 6531320 140736267239168 140736267236856 5641063 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21519/statm: 45952 37570 284 571 0 45373 0
Current children cumulated CPU time (s) 3.01
Current children cumulated vsize (KiB) 193020

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

[startup+3.20032 s]
/proc/loadavg: 1.02 1.01 0.91 2/62 21519
/proc/meminfo: memFree=323944/1022884 swapFree=0/0
[pid=21505] ppid=21504 vsize=9212 CPUtime=3.08
/proc/21505/stat : 21505 (aspuncud-basic) S 21504 21505 1733 0 -1 4202496 764 65251 0 0 0 0 280 28 20 0 1 0 115377024 9433088 365 18446744073709551615 4194304 5129932 140736286133152 140736286131216 140437463499870 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21505/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 9212

[startup+3.60033 s]
/proc/loadavg: 1.02 1.01 0.91 2/63 21521
/proc/meminfo: memFree=335716/1022884 swapFree=0/0
[pid=21505] ppid=21504 vsize=9212 CPUtime=3.08
/proc/21505/stat : 21505 (aspuncud-basic) S 21504 21505 1733 0 -1 4202496 764 65251 0 0 0 0 280 28 20 0 1 0 115377024 9433088 365 18446744073709551615 4194304 5129932 140736286133152 140736286131216 140437463499870 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21505/statm: 2303 365 303 229 0 63 0
[pid=21520] ppid=21505 vsize=55996 CPUtime=0.4
/proc/21520/stat : 21520 (unclasp) R 21505 21505 1733 0 -1 4202496 16229 0 0 0 36 4 0 0 20 0 1 0 115377341 57339904 13540 18446744073709551615 4194304 6012874 140736998119216 140736998118536 4855815 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21520/statm: 13999 13540 226 444 0 13547 0
[pid=21521] ppid=21505 vsize=22188 CPUtime=0
/proc/21521/stat : 21521 (parse.py) S 21505 21505 1733 0 -1 4202496 1328 0 0 0 0 0 0 0 20 0 1 0 115377341 22720512 1139 18446744073709551615 4194304 6642060 140735647068288 140735647066328 140112758138656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21521/statm: 5547 1139 508 598 0 633 0
Current children cumulated CPU time (s) 3.48
Current children cumulated vsize (KiB) 87396

[startup+3.80031 s]
/proc/loadavg: 1.02 1.01 0.91 2/63 21521
/proc/meminfo: memFree=335716/1022884 swapFree=0/0
[pid=21505] ppid=21504 vsize=9212 CPUtime=3.08
/proc/21505/stat : 21505 (aspuncud-basic) S 21504 21505 1733 0 -1 4202496 764 65251 0 0 0 0 280 28 20 0 1 0 115377024 9433088 365 18446744073709551615 4194304 5129932 140736286133152 140736286131216 140437463499870 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21505/statm: 2303 365 303 229 0 63 0
[pid=21520] ppid=21505 vsize=55996 CPUtime=0.6
/proc/21520/stat : 21520 (unclasp) R 21505 21505 1733 0 -1 4202496 16235 0 0 0 56 4 0 0 20 0 1 0 115377341 57339904 13546 18446744073709551615 4194304 6012874 140736998119216 140736998118536 4855815 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21520/statm: 13999 13546 226 444 0 13547 0
[pid=21521] ppid=21505 vsize=22188 CPUtime=0
/proc/21521/stat : 21521 (parse.py) S 21505 21505 1733 0 -1 4202496 1356 0 0 0 0 0 0 0 20 0 1 0 115377341 22720512 1167 18446744073709551615 4194304 6642060 140735647068288 140735647066376 140112758138656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21521/statm: 5547 1167 508 598 0 633 0
Current children cumulated CPU time (s) 3.68
Current children cumulated vsize (KiB) 87396

[startup+3.90032 s]
/proc/loadavg: 1.02 1.01 0.91 2/63 21521
/proc/meminfo: memFree=335716/1022884 swapFree=0/0
[pid=21505] ppid=21504 vsize=9212 CPUtime=3.08
/proc/21505/stat : 21505 (aspuncud-basic) S 21504 21505 1733 0 -1 4202496 764 65251 0 0 0 0 280 28 20 0 1 0 115377024 9433088 365 18446744073709551615 4194304 5129932 140736286133152 140736286131216 140437463499870 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21505/statm: 2303 365 303 229 0 63 0
[pid=21520] ppid=21505 vsize=55996 CPUtime=0.7
/proc/21520/stat : 21520 (unclasp) R 21505 21505 1733 0 -1 4202496 16235 0 0 0 66 4 0 0 20 0 1 0 115377341 57339904 13546 18446744073709551615 4194304 6012874 140736998119216 140736998118536 4855826 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21520/statm: 13999 13546 226 444 0 13547 0
[pid=21521] ppid=21505 vsize=22188 CPUtime=0
/proc/21521/stat : 21521 (parse.py) S 21505 21505 1733 0 -1 4202496 1356 0 0 0 0 0 0 0 20 0 1 0 115377341 22720512 1167 18446744073709551615 4194304 6642060 140735647068288 140735647066376 140112758138656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21521/statm: 5547 1167 508 598 0 633 0
Current children cumulated CPU time (s) 3.78
Current children cumulated vsize (KiB) 87396

Child status: 0
Real time (s): 3.96586
CPU time (s): 3.89224
CPU user time (s): 3.52422
CPU system time (s): 0.368023
CPU usage (%): 98.1437
Max. virtual memory (cumulated for all children) (KiB): 193180

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.52422
system time used= 0.368023
maximum resident set size= 159524
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 83928
page faults= 0
swaps= 0
block input operations= 27176
block output operations= 20992
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 129
involuntary context switches= 530

runsolver used 0.012 second user time and 0.012 second system time

The end