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/bccf69ae-db9e-11df-9a24-00163e3d3b7c.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/real/bccf69ae-db9e-11df-9a24-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/paranoid-size/real/bccf69ae-db9e-11df-9a24-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.04 1.01 0.91 2/60 21461
/proc/meminfo: memFree=437676/1022884 swapFree=0/0
[pid=21461] ppid=21460 vsize=3152 CPUtime=0
/proc/21461/stat : 21461 (runsolver) R 21460 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115374946 3227648 32 18446744073709551615 134512640 134586868 4287023600 4287021648 4151981104 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/21461/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.13003 s]
/proc/loadavg: 1.04 1.01 0.91 2/60 21461
/proc/meminfo: memFree=437676/1022884 swapFree=0/0
[pid=21461] ppid=21460 vsize=9212 CPUtime=0.04
/proc/21461/stat : 21461 (aspuncud-basic) S 21460 21461 1733 0 -1 4202496 700 2810 0 0 0 1 2 1 20 0 1 0 115374946 9433088 365 18446744073709551615 4194304 5129932 140736365790640 140736365789296 140050478609502 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21461/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200367 s]
/proc/loadavg: 1.04 1.01 0.91 2/60 21461
/proc/meminfo: memFree=437676/1022884 swapFree=0/0
[pid=21461] ppid=21460 vsize=9212 CPUtime=0.04
/proc/21461/stat : 21461 (aspuncud-basic) S 21460 21461 1733 0 -1 4202496 700 2810 0 0 0 1 2 1 20 0 1 0 115374946 9433088 365 18446744073709551615 4194304 5129932 140736365790640 140736365789296 140050478609502 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21461/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300344 s]
/proc/loadavg: 1.04 1.01 0.91 2/60 21461
/proc/meminfo: memFree=437676/1022884 swapFree=0/0
[pid=21461] ppid=21460 vsize=9212 CPUtime=0.04
/proc/21461/stat : 21461 (aspuncud-basic) S 21460 21461 1733 0 -1 4202496 700 2810 0 0 0 1 2 1 20 0 1 0 115374946 9433088 365 18446744073709551615 4194304 5129932 140736365790640 140736365789296 140050478609502 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21461/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700251 s]
/proc/loadavg: 1.04 1.01 0.91 2/60 21461
/proc/meminfo: memFree=437676/1022884 swapFree=0/0
[pid=21461] ppid=21460 vsize=9212 CPUtime=0.04
/proc/21461/stat : 21461 (aspuncud-basic) S 21460 21461 1733 0 -1 4202496 700 2810 0 0 0 1 2 1 20 0 1 0 115374946 9433088 365 18446744073709551615 4194304 5129932 140736365790640 140736365789296 140050478609502 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21461/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50033 s]
/proc/loadavg: 1.04 1.01 0.91 2/62 21474
/proc/meminfo: memFree=401940/1022884 swapFree=0/0
[pid=21461] ppid=21460 vsize=9212 CPUtime=0.04
/proc/21461/stat : 21461 (aspuncud-basic) S 21460 21461 1733 0 -1 4202496 700 2810 0 0 0 1 2 1 20 0 1 0 115374946 9433088 365 18446744073709551615 4194304 5129932 140736365790640 140736365789296 140050478609502 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21461/statm: 2303 365 303 229 0 63 0
[pid=21474] ppid=21461 vsize=50500 CPUtime=1.37
/proc/21474/stat : 21474 (cudf2lp) R 21461 21461 1733 0 -1 4202496 14090 0 1 0 128 9 0 0 20 0 1 0 115374949 51712000 10691 18446744073709551615 4194304 5690517 140737078863072 140737078860728 4961154 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/21474/statm: 12625 10691 160 366 0 12256 0
Current children cumulated CPU time (s) 1.41
Current children cumulated vsize (KiB) 59712

[startup+3.10032 s]
/proc/loadavg: 1.04 1.01 0.91 2/62 21475
/proc/meminfo: memFree=414216/1022884 swapFree=0/0
[pid=21461] ppid=21460 vsize=9212 CPUtime=1.96
/proc/21461/stat : 21461 (aspuncud-basic) S 21460 21461 1733 0 -1 4202496 727 20694 0 1 0 1 179 16 20 0 1 0 115374946 9433088 365 18446744073709551615 4194304 5129932 140736365790640 140736365789296 140050478609502 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21461/statm: 2303 365 303 229 0 63 0
[pid=21475] ppid=21461 vsize=44952 CPUtime=1.04
/proc/21475/stat : 21475 (gringo) R 21461 21461 1733 0 -1 4202496 12008 0 0 0 96 8 0 0 20 0 1 0 115375150 46030848 9388 18446744073709551615 4194304 6531320 140734212177680 140734212174664 4359041 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21475/statm: 11238 9388 280 571 0 10659 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 54164

[startup+6.30124 s]
/proc/loadavg: 1.04 1.01 0.91 2/63 21477
/proc/meminfo: memFree=355680/1022884 swapFree=0/0
[pid=21461] ppid=21460 vsize=9212 CPUtime=5.03
/proc/21461/stat : 21461 (aspuncud-basic) S 21460 21461 1733 0 -1 4202496 767 65249 0 1 0 1 456 46 20 0 1 0 115374946 9433088 365 18446744073709551615 4194304 5129932 140736365790640 140736365788704 140050478609502 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21461/statm: 2303 365 303 229 0 63 0
[pid=21476] ppid=21461 vsize=55996 CPUtime=1.11
/proc/21476/stat : 21476 (unclasp) R 21461 21461 1733 0 -1 4202496 16244 0 0 0 103 8 0 0 20 0 1 0 115375461 57339904 12532 18446744073709551615 4194304 6012874 140733249336688 140733249336088 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21476/statm: 13999 12532 234 444 0 13547 0
[pid=21477] ppid=21461 vsize=22356 CPUtime=0.02
/proc/21477/stat : 21477 (parse.py) S 21461 21461 1733 0 -1 4202496 1380 0 0 0 1 1 0 0 20 0 1 0 115375461 22892544 1191 18446744073709551615 4194304 6642060 140733367656320 140733367654360 139753230550816 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21477/statm: 5589 1191 508 598 0 675 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 87564

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

[startup+6.30124 s]
/proc/loadavg: 1.04 1.01 0.91 2/63 21477
/proc/meminfo: memFree=355680/1022884 swapFree=0/0
[pid=21461] ppid=21460 vsize=9212 CPUtime=5.03
/proc/21461/stat : 21461 (aspuncud-basic) S 21460 21461 1733 0 -1 4202496 767 65249 0 1 0 1 456 46 20 0 1 0 115374946 9433088 365 18446744073709551615 4194304 5129932 140736365790640 140736365788704 140050478609502 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21461/statm: 2303 365 303 229 0 63 0
[pid=21476] ppid=21461 vsize=55996 CPUtime=1.11
/proc/21476/stat : 21476 (unclasp) R 21461 21461 1733 0 -1 4202496 16244 0 0 0 103 8 0 0 20 0 1 0 115375461 57339904 12532 18446744073709551615 4194304 6012874 140733249336688 140733249336088 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21476/statm: 13999 12532 234 444 0 13547 0
[pid=21477] ppid=21461 vsize=22356 CPUtime=0.02
/proc/21477/stat : 21477 (parse.py) S 21461 21461 1733 0 -1 4202496 1380 0 0 0 1 1 0 0 20 0 1 0 115375461 22892544 1191 18446744073709551615 4194304 6642060 140733367656320 140733367654360 139753230550816 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21477/statm: 5589 1191 508 598 0 675 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 87564

Child status: 0
Real time (s): 6.33779
CPU time (s): 6.22839
CPU user time (s): 5.62835
CPU system time (s): 0.600037
CPU usage (%): 98.2738
Max. virtual memory (cumulated for all children) (KiB): 195072

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 5.62835
system time used= 0.600037
maximum resident set size= 159528
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 83927
page faults= 1
swaps= 0
block input operations= 27320
block output operations= 20992
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 127
involuntary context switches= 801

runsolver used 0.012 second user time and 0.036002 second system time

The end