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: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/ed1cc19e-51b7-11e0-8436-00163e1e087d.cudf.dudf-real.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-real//ed1cc19e-51b7-11e0-8436-00163e1e087d.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/ed1cc19e-51b7-11e0-8436-00163e1e087d.cudf.dudf-real.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 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.34 1.42 1.36 4/34 30745
/proc/meminfo: memFree=281448/1048576 swapFree=0/0
[pid=30744] ppid=30743 vsize=2568 CPUtime=0
/proc/30744/stat : 30744 (packup2mp4pa-0.) R 30743 30744 4778 34817 4778 4202496 360 0 0 0 0 0 0 0 25 0 1 0 11266792 2629632 273 1283457024 134512640 135304128 4294730176 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/30744/statm: 642 273 233 194 0 29 0
[pid=30745] ppid=30744 vsize=2568 CPUtime=0
/proc/30745/stat : 30745 (packup2mp4pa-0.) R 30744 30744 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 11266792 2629632 40 1283457024 134512640 135304128 4294730176 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/30745/statm: 642 40 0 194 0 29 0

[startup+0.168961 s]
/proc/loadavg: 1.34 1.42 1.36 4/34 30745
/proc/meminfo: memFree=281448/1048576 swapFree=0/0
[pid=30744] ppid=30743 vsize=2568 CPUtime=0
/proc/30744/stat : 30744 (packup2mp4pa-0.) S 30743 30744 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11266792 2629632 273 1283457024 134512640 135304128 4294730176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30744/statm: 642 273 233 194 0 29 0
[pid=30745] ppid=30744 vsize=9332 CPUtime=0.16
/proc/30745/stat : 30745 (packup) R 30744 30744 4778 34817 4778 4202496 1825 0 0 0 16 0 0 0 25 0 1 0 11266792 9555968 1754 1283457024 134512640 134752139 4293222432 18446744073709551615 134558080 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30745/statm: 2333 1754 286 59 0 1497 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 11900

[startup+0.208968 s]
/proc/loadavg: 1.34 1.42 1.36 4/34 30745
/proc/meminfo: memFree=281448/1048576 swapFree=0/0
[pid=30744] ppid=30743 vsize=2568 CPUtime=0
/proc/30744/stat : 30744 (packup2mp4pa-0.) S 30743 30744 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11266792 2629632 273 1283457024 134512640 135304128 4294730176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30744/statm: 642 273 233 194 0 29 0
[pid=30745] ppid=30744 vsize=10520 CPUtime=0.2
/proc/30745/stat : 30745 (packup) R 30744 30744 4778 34817 4778 4202496 2118 0 0 0 20 0 0 0 25 0 1 0 11266792 10772480 2047 1283457024 134512640 134752139 4293222432 18446744073709551615 134681718 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30745/statm: 2630 2047 286 59 0 1794 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13088

[startup+0.308981 s]
/proc/loadavg: 1.34 1.42 1.36 4/34 30745
/proc/meminfo: memFree=281448/1048576 swapFree=0/0
[pid=30744] ppid=30743 vsize=2568 CPUtime=0
/proc/30744/stat : 30744 (packup2mp4pa-0.) S 30743 30744 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11266792 2629632 273 1283457024 134512640 135304128 4294730176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30744/statm: 642 273 233 194 0 29 0
[pid=30745] ppid=30744 vsize=13376 CPUtime=0.3
/proc/30745/stat : 30745 (packup) R 30744 30744 4778 34817 4778 4202496 2827 0 0 0 30 0 0 0 25 0 1 0 11266792 13697024 2756 1283457024 134512640 134752139 4293222432 18446744073709551615 4159616751 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30745/statm: 3344 2756 286 59 0 2508 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15944

[startup+0.70904 s]
/proc/loadavg: 1.34 1.42 1.36 4/34 30745
/proc/meminfo: memFree=281448/1048576 swapFree=0/0
[pid=30744] ppid=30743 vsize=2568 CPUtime=0
/proc/30744/stat : 30744 (packup2mp4pa-0.) S 30743 30744 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11266792 2629632 273 1283457024 134512640 135304128 4294730176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30744/statm: 642 273 233 194 0 29 0
[pid=30745] ppid=30744 vsize=23604 CPUtime=0.7
/proc/30745/stat : 30745 (packup) R 30744 30744 4778 34817 4778 4202496 5379 0 0 0 70 0 0 0 25 0 1 0 11266792 24170496 5308 1283457024 134512640 134752139 4293222432 18446744073709551615 134681672 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30745/statm: 5901 5308 286 59 0 5065 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 26172

[startup+1.51318 s]
/proc/loadavg: 1.34 1.42 1.36 2/35 30746
/proc/meminfo: memFree=250580/1048576 swapFree=0/0
[pid=30744] ppid=30743 vsize=2568 CPUtime=0
/proc/30744/stat : 30744 (packup2mp4pa-0.) S 30743 30744 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11266792 2629632 273 1283457024 134512640 135304128 4294730176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30744/statm: 642 273 233 194 0 29 0
[pid=30745] ppid=30744 vsize=34304 CPUtime=1.09
/proc/30745/stat : 30745 (packup) S 30744 30744 4778 34817 4778 4202496 8111 0 0 0 102 7 0 0 24 0 1 0 11266792 35127296 7932 1283457024 134512640 134752139 4293222432 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30745/statm: 8576 7932 324 59 0 7740 0
Current children cumulated CPU time (s) 1.09
Current children cumulated vsize (KiB) 36872

[startup+3.11394 s]
/proc/loadavg: 1.34 1.42 1.36 2/37 30748
/proc/meminfo: memFree=210744/1048576 swapFree=0/0
[pid=30744] ppid=30743 vsize=2568 CPUtime=0
/proc/30744/stat : 30744 (packup2mp4pa-0.) S 30743 30744 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11266792 2629632 273 1283457024 134512640 135304128 4294730176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30744/statm: 642 273 233 194 0 29 0
[pid=30745] ppid=30744 vsize=34308 CPUtime=2.96
/proc/30745/stat : 30745 (packup) R 30744 30744 4778 34817 4778 4202496 8173 19028 0 0 110 13 157 16 18 0 1 0 11266792 35131392 7941 1283457024 134512640 134752139 4293222432 18446744073709551615 4159140375 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30745/statm: 8577 7941 332 59 0 7741 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 36876

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

[startup+3.20396 s]
/proc/loadavg: 1.34 1.42 1.36 2/37 30748
/proc/meminfo: memFree=210744/1048576 swapFree=0/0
[pid=30744] ppid=30743 vsize=2568 CPUtime=0
/proc/30744/stat : 30744 (packup2mp4pa-0.) S 30743 30744 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11266792 2629632 273 1283457024 134512640 135304128 4294730176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30744/statm: 642 273 233 194 0 29 0
[pid=30745] ppid=30744 vsize=34308 CPUtime=2.99
/proc/30745/stat : 30745 (packup) S 30744 30744 4778 34817 4778 4202496 8174 19028 0 0 110 16 157 16 18 0 1 0 11266792 35131392 7941 1283457024 134512640 134752139 4293222432 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30745/statm: 8577 7941 332 59 0 7741 0
Current children cumulated CPU time (s) 2.99
Current children cumulated vsize (KiB) 36876

[startup+4.00413 s]
/proc/loadavg: 1.34 1.42 1.36 2/37 30750
/proc/meminfo: memFree=245216/1048576 swapFree=0/0
[pid=30744] ppid=30743 vsize=2568 CPUtime=0
/proc/30744/stat : 30744 (packup2mp4pa-0.) S 30743 30744 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11266792 2629632 273 1283457024 134512640 135304128 4294730176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30744/statm: 642 273 233 194 0 29 0
[pid=30745] ppid=30744 vsize=34308 CPUtime=2.99
/proc/30745/stat : 30745 (packup) S 30744 30744 4778 34817 4778 4202496 8174 19028 0 0 110 16 157 16 18 0 1 0 11266792 35131392 7941 1283457024 134512640 134752139 4293222432 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30745/statm: 8577 7941 332 59 0 7741 0
[pid=30749] ppid=30745 vsize=1668 CPUtime=0
/proc/30749/stat : 30749 (sh) S 30745 30744 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11267106 1708032 123 1283457024 134512640 134593992 4286966528 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30749/statm: 417 123 108 20 0 44 0
[pid=30750] ppid=30749 vsize=32108 CPUtime=0.86
/proc/30750/stat : 30750 (minisatp_32) R 30749 30744 4778 34817 4778 4202496 9856 0 0 0 80 6 0 0 23 0 1 0 11267107 32878592 7331 1283457024 134512640 135413687 4292276272 18446744073709551615 134686343 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30750/statm: 8027 7331 108 220 0 7805 0
Current children cumulated CPU time (s) 3.85
Current children cumulated vsize (KiB) 70652

[startup+4.80434 s]
/proc/loadavg: 1.31 1.41 1.35 2/37 30750
/proc/meminfo: memFree=192516/1048576 swapFree=0/0
[pid=30744] ppid=30743 vsize=2568 CPUtime=0
/proc/30744/stat : 30744 (packup2mp4pa-0.) S 30743 30744 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11266792 2629632 273 1283457024 134512640 135304128 4294730176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30744/statm: 642 273 233 194 0 29 0
[pid=30745] ppid=30744 vsize=34308 CPUtime=2.99
/proc/30745/stat : 30745 (packup) S 30744 30744 4778 34817 4778 4202496 8174 19028 0 0 110 16 157 16 18 0 1 0 11266792 35131392 7941 1283457024 134512640 134752139 4293222432 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30745/statm: 8577 7941 332 59 0 7741 0
[pid=30749] ppid=30745 vsize=1668 CPUtime=0
/proc/30749/stat : 30749 (sh) S 30745 30744 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11267106 1708032 123 1283457024 134512640 134593992 4286966528 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30749/statm: 417 123 108 20 0 44 0
[pid=30750] ppid=30749 vsize=68604 CPUtime=1.65
/proc/30750/stat : 30750 (minisatp_32) R 30749 30744 4778 34817 4778 4202496 21533 0 0 0 154 11 0 0 25 0 1 0 11267107 70250496 15075 1283457024 134512640 135413687 4292276272 18446744073709551615 134689048 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30750/statm: 17151 15075 108 220 0 16929 0
Current children cumulated CPU time (s) 4.64
Current children cumulated vsize (KiB) 107148

[startup+5.20445 s]
/proc/loadavg: 1.31 1.41 1.35 2/37 30750
/proc/meminfo: memFree=192516/1048576 swapFree=0/0
[pid=30744] ppid=30743 vsize=2568 CPUtime=0
/proc/30744/stat : 30744 (packup2mp4pa-0.) S 30743 30744 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11266792 2629632 273 1283457024 134512640 135304128 4294730176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30744/statm: 642 273 233 194 0 29 0
[pid=30745] ppid=30744 vsize=34308 CPUtime=2.99
/proc/30745/stat : 30745 (packup) S 30744 30744 4778 34817 4778 4202496 8174 19028 0 0 110 16 157 16 18 0 1 0 11266792 35131392 7941 1283457024 134512640 134752139 4293222432 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30745/statm: 8577 7941 332 59 0 7741 0
[pid=30749] ppid=30745 vsize=1668 CPUtime=0
/proc/30749/stat : 30749 (sh) S 30745 30744 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11267106 1708032 123 1283457024 134512640 134593992 4286966528 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30749/statm: 417 123 108 20 0 44 0
[pid=30750] ppid=30749 vsize=64168 CPUtime=2.05
/proc/30750/stat : 30750 (minisatp_32) R 30749 30744 4778 34817 4778 4202496 22929 0 0 0 193 12 0 0 25 0 1 0 11267107 65708032 14444 1283457024 134512640 135413687 4292276272 18446744073709551615 134597339 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30750/statm: 16042 14444 117 220 0 15820 0
Current children cumulated CPU time (s) 5.04
Current children cumulated vsize (KiB) 102712

[startup+5.30447 s]
/proc/loadavg: 1.31 1.41 1.35 2/37 30750
/proc/meminfo: memFree=192516/1048576 swapFree=0/0
[pid=30744] ppid=30743 vsize=2568 CPUtime=0
/proc/30744/stat : 30744 (packup2mp4pa-0.) S 30743 30744 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 25 0 1 0 11266792 2629632 273 1283457024 134512640 135304128 4294730176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30744/statm: 642 273 233 194 0 29 0
[pid=30745] ppid=30744 vsize=33528 CPUtime=5.14
/proc/30745/stat : 30745 (packup) R 30744 30744 4778 34817 4778 4202496 15218 42105 0 0 112 22 350 30 18 0 1 0 11266792 34332672 7759 1283457024 134512640 134752139 4293222432 18446744073709551615 4157674909 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30745/statm: 8382 7759 345 59 0 7546 0
Current children cumulated CPU time (s) 5.14
Current children cumulated vsize (KiB) 36096

Child status: 0
Real time (s): 5.32554
CPU time (s): 5.18032
CPU user time (s): 4.64429
CPU system time (s): 0.536033
CPU usage (%): 97.2732
Max. virtual memory (cumulated for all children) (KiB): 113520

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.64429
system time used= 0.536033
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 57956
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 13
involuntary context switches= 104

runsolver used 0.004 second user time and 0 second system time

The end