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/ed1cc19e-51b7-11e0-8436-00163e1e087d.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/real/ed1cc19e-51b7-11e0-8436-00163e1e087d.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/paranoid-size/real/ed1cc19e-51b7-11e0-8436-00163e1e087d.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.01 1.01 0.91 2/60 21593
/proc/meminfo: memFree=417464/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=3152 CPUtime=0
/proc/21593/stat : 21593 (runsolver) R 21592 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115382019 3227648 33 18446744073709551615 134512640 134586868 4291040096 4291038144 4151682096 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.158724 s]
/proc/loadavg: 1.01 1.01 0.91 2/60 21593
/proc/meminfo: memFree=417464/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=9212 CPUtime=0.02
/proc/21593/stat : 21593 (aspuncud-basic) S 21592 21593 1733 0 -1 4202496 700 2807 0 0 0 0 2 0 20 0 1 0 115382019 9433088 365 18446744073709551615 4194304 5129932 140735496562576 140735496561232 140516934227038 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200379 s]
/proc/loadavg: 1.01 1.01 0.91 2/60 21593
/proc/meminfo: memFree=417464/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=9212 CPUtime=0.02
/proc/21593/stat : 21593 (aspuncud-basic) S 21592 21593 1733 0 -1 4202496 700 2807 0 0 0 0 2 0 20 0 1 0 115382019 9433088 365 18446744073709551615 4194304 5129932 140735496562576 140735496561232 140516934227038 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300311 s]
/proc/loadavg: 1.01 1.01 0.91 2/60 21593
/proc/meminfo: memFree=417464/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=9212 CPUtime=0.02
/proc/21593/stat : 21593 (aspuncud-basic) S 21592 21593 1733 0 -1 4202496 700 2807 0 0 0 0 2 0 20 0 1 0 115382019 9433088 365 18446744073709551615 4194304 5129932 140735496562576 140735496561232 140516934227038 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.70032 s]
/proc/loadavg: 1.01 1.01 0.91 2/60 21593
/proc/meminfo: memFree=417464/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=9212 CPUtime=0.02
/proc/21593/stat : 21593 (aspuncud-basic) S 21592 21593 1733 0 -1 4202496 700 2807 0 0 0 0 2 0 20 0 1 0 115382019 9433088 365 18446744073709551615 4194304 5129932 140735496562576 140735496561232 140516934227038 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21593/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 1.01 0.91 2/62 21606
/proc/meminfo: memFree=382100/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=9212 CPUtime=0.02
/proc/21593/stat : 21593 (aspuncud-basic) S 21592 21593 1733 0 -1 4202496 700 2807 0 0 0 0 2 0 20 0 1 0 115382019 9433088 365 18446744073709551615 4194304 5129932 140735496562576 140735496561232 140516934227038 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 2303 365 303 229 0 63 0
[pid=21606] ppid=21593 vsize=50356 CPUtime=1.25
/proc/21606/stat : 21606 (cudf2lp) R 21593 21593 1733 0 -1 4202496 14237 0 0 0 117 8 0 0 20 0 1 0 115382021 51564544 10837 18446744073709551615 4194304 5690517 140735999797216 140735999794856 4247165 0 0 16781316 0 0 0 0 17 0 0 0 21 0 0
/proc/21606/statm: 12589 10837 160 366 0 12220 0
Current children cumulated CPU time (s) 1.27
Current children cumulated vsize (KiB) 59568

[startup+3.10025 s]
/proc/loadavg: 1.01 1.01 0.91 2/62 21607
/proc/meminfo: memFree=394120/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=9212 CPUtime=1.95
/proc/21593/stat : 21593 (aspuncud-basic) S 21592 21593 1733 0 -1 4202496 727 23741 0 0 0 0 183 12 20 0 1 0 115382019 9433088 365 18446744073709551615 4194304 5129932 140735496562576 140735496561232 140516934227038 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 2303 365 303 229 0 63 0
[pid=21607] ppid=21593 vsize=67872 CPUtime=0.89
/proc/21607/stat : 21607 (gringo) R 21593 21593 1733 0 -1 4202496 17530 0 0 0 82 7 0 0 20 0 1 0 115382238 69500928 14910 18446744073709551615 4194304 6531320 140736683513520 140736683509528 5521035 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21607/statm: 16968 14910 280 571 0 16389 0
Current children cumulated CPU time (s) 2.84
Current children cumulated vsize (KiB) 77084

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

[startup+3.20031 s]
/proc/loadavg: 1.01 1.01 0.91 2/62 21607
/proc/meminfo: memFree=394120/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=9212 CPUtime=1.95
/proc/21593/stat : 21593 (aspuncud-basic) S 21592 21593 1733 0 -1 4202496 727 23741 0 0 0 0 183 12 20 0 1 0 115382019 9433088 365 18446744073709551615 4194304 5129932 140735496562576 140735496561232 140516934227038 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 2303 365 303 229 0 63 0
[pid=21607] ppid=21593 vsize=71320 CPUtime=0.99
/proc/21607/stat : 21607 (gringo) R 21593 21593 1733 0 -1 4202496 18482 0 0 0 91 8 0 0 20 0 1 0 115382238 73031680 15862 18446744073709551615 4194304 6531320 140736683513520 140736683510136 4590961 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21607/statm: 17830 15862 280 571 0 17251 0
Current children cumulated CPU time (s) 2.94
Current children cumulated vsize (KiB) 80532

[startup+4.80033 s]
/proc/loadavg: 1.01 1.01 0.91 2/63 21609
/proc/meminfo: memFree=364236/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=9212 CPUtime=4.07
/proc/21593/stat : 21593 (aspuncud-basic) S 21592 21593 1733 0 -1 4202496 768 73110 0 0 0 0 373 34 20 0 1 0 115382019 9433088 365 18446744073709551615 4194304 5129932 140735496562576 140735496560640 140516934227038 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 2303 365 303 229 0 63 0
[pid=21608] ppid=21593 vsize=62340 CPUtime=0.46
/proc/21608/stat : 21608 (unclasp) R 21593 21593 1733 0 -1 4202496 17981 0 0 0 40 6 0 0 20 0 1 0 115382451 63836160 15191 18446744073709551615 4194304 6012874 140736583248496 140736583247816 4548198 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21608/statm: 15585 15191 226 444 0 15133 0
[pid=21609] ppid=21593 vsize=22188 CPUtime=0
/proc/21609/stat : 21609 (parse.py) S 21593 21593 1733 0 -1 4202496 1331 0 0 0 0 0 0 0 20 0 1 0 115382451 22720512 1141 18446744073709551615 4194304 6642060 140735362676080 140735362674088 140294541301536 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21609/statm: 5547 1141 508 598 0 633 0
Current children cumulated CPU time (s) 4.53
Current children cumulated vsize (KiB) 93740

[startup+5.20031 s]
/proc/loadavg: 1.01 1.01 0.91 2/63 21609
/proc/meminfo: memFree=364236/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=9212 CPUtime=4.07
/proc/21593/stat : 21593 (aspuncud-basic) S 21592 21593 1733 0 -1 4202496 768 73110 0 0 0 0 373 34 20 0 1 0 115382019 9433088 365 18446744073709551615 4194304 5129932 140735496562576 140735496560640 140516934227038 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 2303 365 303 229 0 63 0
[pid=21608] ppid=21593 vsize=62340 CPUtime=0.86
/proc/21608/stat : 21608 (unclasp) R 21593 21593 1733 0 -1 4202496 17992 0 0 0 80 6 0 0 20 0 1 0 115382451 63836160 15202 18446744073709551615 4194304 6012874 140736583248496 140736583247784 4530787 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21608/statm: 15585 15202 226 444 0 15133 0
[pid=21609] ppid=21593 vsize=22336 CPUtime=0
/proc/21609/stat : 21609 (parse.py) S 21593 21593 1733 0 -1 4202496 1363 0 0 0 0 0 0 0 20 0 1 0 115382451 22872064 1173 18446744073709551615 4194304 6642060 140735362676080 140735362674040 140294541301536 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21609/statm: 5584 1173 508 598 0 670 0
Current children cumulated CPU time (s) 4.93
Current children cumulated vsize (KiB) 93888

[startup+5.40044 s]
/proc/loadavg: 1.01 1.01 0.91 2/63 21609
/proc/meminfo: memFree=364236/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=9212 CPUtime=5.01
/proc/21593/stat : 21593 (aspuncud-basic) S 21592 21593 1733 0 -1 4202496 801 92519 0 0 0 0 459 42 20 0 1 0 115382019 9433088 365 18446744073709551615 4194304 5129932 140735496562576 140735496560128 140516934227038 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 5.01
Current children cumulated vsize (KiB) 9212

[startup+5.50033 s]
/proc/loadavg: 1.01 1.01 0.91 1/62 21610
/proc/meminfo: memFree=393384/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=9212 CPUtime=5.01
/proc/21593/stat : 21593 (aspuncud-basic) S 21592 21593 1733 0 -1 4202496 801 92519 0 0 0 0 459 42 20 0 1 0 115382019 9433088 365 18446744073709551615 4194304 5129932 140735496562576 140735496560128 140516934227038 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 2303 365 303 229 0 63 0
[pid=21610] ppid=21593 vsize=4060 CPUtime=0
/proc/21610/stat : 21610 (rm) D 21593 21593 1733 0 -1 4202496 209 0 0 0 0 0 0 0 20 0 1 0 115382547 4157440 142 18446744073709551615 4194304 4250524 140736284154960 140736284154184 140495706364445 0 0 16781316 0 0 0 0 17 0 0 0 20 0 0
/proc/21610/statm: 1015 142 119 14 0 67 0
Current children cumulated CPU time (s) 5.01
Current children cumulated vsize (KiB) 13272

Child status: 0
Real time (s): 5.52151
CPU time (s): 5.04031
CPU user time (s): 4.60429
CPU system time (s): 0.436027
CPU usage (%): 91.2851
Max. virtual memory (cumulated for all children) (KiB): 218112

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.60429
system time used= 0.436027
maximum resident set size= 178784
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 93554
page faults= 0
swaps= 0
block input operations= 34072
block output operations= 24088
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 151
involuntary context switches= 650

runsolver used 0.004 second user time and 0.032002 second system time

The end