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/e2f6303a-4fe9-11e0-aa4f-00163e1e087d.cudf.dudf-real.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-real//e2f6303a-4fe9-11e0-aa4f-00163e1e087d.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/e2f6303a-4fe9-11e0-aa4f-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.30 1.42 1.35 5/34 29865
/proc/meminfo: memFree=277196/1048576 swapFree=0/0
[pid=29864] ppid=29863 vsize=2572 CPUtime=0
/proc/29864/stat : 29864 (packup2mp4pa-0.) R 29863 29864 4778 34817 4778 4202496 362 0 0 0 0 0 0 0 25 0 1 0 11255946 2633728 275 1283457024 134512640 135304128 4290118992 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/29864/statm: 643 275 233 194 0 30 0
[pid=29865] ppid=29864 vsize=2572 CPUtime=0
/proc/29865/stat : 29865 (packup2mp4pa-0.) R 29864 29864 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 11255946 2633728 42 1283457024 134512640 135304128 4290118992 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/29865/statm: 643 42 0 194 0 30 0

[startup+0.131159 s]
/proc/loadavg: 1.30 1.42 1.35 5/34 29865
/proc/meminfo: memFree=277196/1048576 swapFree=0/0
[pid=29864] ppid=29863 vsize=2572 CPUtime=0
/proc/29864/stat : 29864 (packup2mp4pa-0.) S 29863 29864 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 25 0 1 0 11255946 2633728 275 1283457024 134512640 135304128 4290118992 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29864/statm: 643 275 233 194 0 30 0
[pid=29865] ppid=29864 vsize=8164 CPUtime=0.13
/proc/29865/stat : 29865 (packup) R 29864 29864 4778 34817 4778 4202496 1533 0 0 0 13 0 0 0 25 0 1 0 11255946 8359936 1461 1283457024 134512640 134752139 4287945488 18446744073709551615 4157967928 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/29865/statm: 2041 1461 286 59 0 1205 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 10736

[startup+0.211178 s]
/proc/loadavg: 1.30 1.42 1.35 5/34 29865
/proc/meminfo: memFree=277196/1048576 swapFree=0/0
[pid=29864] ppid=29863 vsize=2572 CPUtime=0
/proc/29864/stat : 29864 (packup2mp4pa-0.) S 29863 29864 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 25 0 1 0 11255946 2633728 275 1283457024 134512640 135304128 4290118992 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29864/statm: 643 275 233 194 0 30 0
[pid=29865] ppid=29864 vsize=10672 CPUtime=0.21
/proc/29865/stat : 29865 (packup) R 29864 29864 4778 34817 4778 4202496 2154 0 0 0 21 0 0 0 25 0 1 0 11255946 10928128 2082 1283457024 134512640 134752139 4287945488 18446744073709551615 134681583 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/29865/statm: 2668 2082 286 59 0 1832 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 13244

[startup+0.311201 s]
/proc/loadavg: 1.30 1.42 1.35 5/34 29865
/proc/meminfo: memFree=277196/1048576 swapFree=0/0
[pid=29864] ppid=29863 vsize=2572 CPUtime=0
/proc/29864/stat : 29864 (packup2mp4pa-0.) S 29863 29864 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 25 0 1 0 11255946 2633728 275 1283457024 134512640 135304128 4290118992 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29864/statm: 643 275 233 194 0 30 0
[pid=29865] ppid=29864 vsize=13508 CPUtime=0.31
/proc/29865/stat : 29865 (packup) R 29864 29864 4778 34817 4778 4202496 2855 0 0 0 31 0 0 0 25 0 1 0 11255946 13832192 2783 1283457024 134512640 134752139 4287945488 18446744073709551615 4157945508 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/29865/statm: 3377 2783 286 59 0 2541 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 16080

[startup+0.711372 s]
/proc/loadavg: 1.30 1.42 1.35 5/34 29865
/proc/meminfo: memFree=277196/1048576 swapFree=0/0
[pid=29864] ppid=29863 vsize=2572 CPUtime=0
/proc/29864/stat : 29864 (packup2mp4pa-0.) S 29863 29864 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 25 0 1 0 11255946 2633728 275 1283457024 134512640 135304128 4290118992 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29864/statm: 643 275 233 194 0 30 0
[pid=29865] ppid=29864 vsize=23748 CPUtime=0.71
/proc/29865/stat : 29865 (packup) R 29864 29864 4778 34817 4778 4202496 5434 0 0 0 70 1 0 0 25 0 1 0 11255946 24317952 5362 1283457024 134512640 134752139 4287945488 18446744073709551615 134681530 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/29865/statm: 5937 5362 286 59 0 5101 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 26320

[startup+1.5115 s]
/proc/loadavg: 1.30 1.42 1.35 4/37 29868
/proc/meminfo: memFree=244912/1048576 swapFree=0/0
[pid=29864] ppid=29863 vsize=2572 CPUtime=0
/proc/29864/stat : 29864 (packup2mp4pa-0.) S 29863 29864 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 25 0 1 0 11255946 2633728 275 1283457024 134512640 135304128 4290118992 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29864/statm: 643 275 233 194 0 30 0
[pid=29865] ppid=29864 vsize=34208 CPUtime=1.08
/proc/29865/stat : 29865 (packup) S 29864 29864 4778 34817 4778 4202496 8078 0 0 0 97 11 0 0 25 0 1 0 11255946 35028992 7898 1283457024 134512640 134752139 4287945488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/29865/statm: 8552 7898 324 59 0 7716 0
[pid=29867] ppid=29865 vsize=1676 CPUtime=0
/proc/29867/stat : 29867 (sh) S 29865 29864 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 25 0 1 0 11256055 1716224 124 1283457024 134512640 134593992 4289377616 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/29867/statm: 419 124 108 20 0 46 0
[pid=29868] ppid=29867 vsize=14528 CPUtime=0.42
/proc/29868/stat : 29868 (minisatp_32) R 29867 29864 4778 34817 4778 4202496 2715 0 0 0 42 0 0 0 25 0 1 0 11256056 14876672 2312 1283457024 134512640 135413687 4292411472 18446744073709551615 134971244 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/29868/statm: 3632 2312 77 220 0 3410 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 52984

[startup+3.11182 s]
/proc/loadavg: 1.30 1.42 1.35 2/37 29868
/proc/meminfo: memFree=200148/1048576 swapFree=0/0
[pid=29864] ppid=29863 vsize=2572 CPUtime=0
/proc/29864/stat : 29864 (packup2mp4pa-0.) S 29863 29864 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 25 0 1 0 11255946 2633728 275 1283457024 134512640 135304128 4290118992 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29864/statm: 643 275 233 194 0 30 0
[pid=29865] ppid=29864 vsize=34212 CPUtime=2.95
/proc/29865/stat : 29865 (packup) S 29864 29864 4778 34817 4778 4202496 8136 18895 0 0 104 20 154 17 18 0 1 0 11255946 35033088 7907 1283457024 134512640 134752139 4287945488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/29865/statm: 8553 7907 332 59 0 7717 0
Current children cumulated CPU time (s) 2.95
Current children cumulated vsize (KiB) 36784

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

[startup+3.21183 s]
/proc/loadavg: 1.30 1.42 1.35 2/37 29868
/proc/meminfo: memFree=200148/1048576 swapFree=0/0
[pid=29864] ppid=29863 vsize=2572 CPUtime=0
/proc/29864/stat : 29864 (packup2mp4pa-0.) S 29863 29864 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 25 0 1 0 11255946 2633728 275 1283457024 134512640 135304128 4290118992 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29864/statm: 643 275 233 194 0 30 0
[pid=29865] ppid=29864 vsize=34212 CPUtime=2.95
/proc/29865/stat : 29865 (packup) S 29864 29864 4778 34817 4778 4202496 8136 18895 0 0 104 20 154 17 18 0 1 0 11255946 35033088 7907 1283457024 134512640 134752139 4287945488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/29865/statm: 8553 7907 332 59 0 7717 0
Current children cumulated CPU time (s) 2.95
Current children cumulated vsize (KiB) 36784

[startup+4.01198 s]
/proc/loadavg: 1.27 1.41 1.35 2/37 29870
/proc/meminfo: memFree=238092/1048576 swapFree=0/0
[pid=29864] ppid=29863 vsize=2572 CPUtime=0
/proc/29864/stat : 29864 (packup2mp4pa-0.) S 29863 29864 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 25 0 1 0 11255946 2633728 275 1283457024 134512640 135304128 4290118992 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29864/statm: 643 275 233 194 0 30 0
[pid=29865] ppid=29864 vsize=34212 CPUtime=2.95
/proc/29865/stat : 29865 (packup) S 29864 29864 4778 34817 4778 4202496 8136 18895 0 0 104 20 154 17 18 0 1 0 11255946 35033088 7907 1283457024 134512640 134752139 4287945488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/29865/statm: 8553 7907 332 59 0 7717 0
[pid=29869] ppid=29865 vsize=1676 CPUtime=0
/proc/29869/stat : 29869 (sh) S 29865 29864 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 18 0 1 0 11256243 1716224 124 1283457024 134512640 134593992 4287808464 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/29869/statm: 419 124 108 20 0 46 0
[pid=29870] ppid=29869 vsize=53068 CPUtime=1.03
/proc/29870/stat : 29870 (minisatp_32) R 29869 29864 4778 34817 4778 4202496 16033 0 0 0 91 12 0 0 23 0 1 0 11256244 54341632 12003 1283457024 134512640 135413687 4288242784 18446744073709551615 134981020 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/29870/statm: 13267 12003 108 220 0 13045 0
Current children cumulated CPU time (s) 3.98
Current children cumulated vsize (KiB) 91528

[startup+4.81212 s]
/proc/loadavg: 1.27 1.41 1.35 2/37 29870
/proc/meminfo: memFree=182416/1048576 swapFree=0/0
[pid=29864] ppid=29863 vsize=2572 CPUtime=0
/proc/29864/stat : 29864 (packup2mp4pa-0.) S 29863 29864 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 25 0 1 0 11255946 2633728 275 1283457024 134512640 135304128 4290118992 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29864/statm: 643 275 233 194 0 30 0
[pid=29865] ppid=29864 vsize=34212 CPUtime=2.95
/proc/29865/stat : 29865 (packup) S 29864 29864 4778 34817 4778 4202496 8136 18895 0 0 104 20 154 17 18 0 1 0 11255946 35033088 7907 1283457024 134512640 134752139 4287945488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/29865/statm: 8553 7907 332 59 0 7717 0
[pid=29869] ppid=29865 vsize=1676 CPUtime=0
/proc/29869/stat : 29869 (sh) S 29865 29864 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 18 0 1 0 11256243 1716224 124 1283457024 134512640 134593992 4287808464 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/29869/statm: 419 124 108 20 0 46 0
[pid=29870] ppid=29869 vsize=68680 CPUtime=1.83
/proc/29870/stat : 29870 (minisatp_32) R 29869 29864 4778 34817 4778 4202496 21565 0 0 0 166 17 0 0 25 0 1 0 11256244 70328320 15124 1283457024 134512640 135413687 4288242784 18446744073709551615 134705555 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/29870/statm: 17170 15124 108 220 0 16948 0
Current children cumulated CPU time (s) 4.78
Current children cumulated vsize (KiB) 107140

[startup+5.01216 s]
/proc/loadavg: 1.27 1.41 1.35 2/37 29870
/proc/meminfo: memFree=182416/1048576 swapFree=0/0
[pid=29864] ppid=29863 vsize=2572 CPUtime=0
/proc/29864/stat : 29864 (packup2mp4pa-0.) S 29863 29864 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 25 0 1 0 11255946 2633728 275 1283457024 134512640 135304128 4290118992 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29864/statm: 643 275 233 194 0 30 0
[pid=29865] ppid=29864 vsize=34212 CPUtime=2.95
/proc/29865/stat : 29865 (packup) S 29864 29864 4778 34817 4778 4202496 8136 18895 0 0 104 20 154 17 18 0 1 0 11255946 35033088 7907 1283457024 134512640 134752139 4287945488 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/29865/statm: 8553 7907 332 59 0 7717 0
[pid=29869] ppid=29865 vsize=1676 CPUtime=0
/proc/29869/stat : 29869 (sh) S 29865 29864 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 18 0 1 0 11256243 1716224 124 1283457024 134512640 134593992 4287808464 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/29869/statm: 419 124 108 20 0 46 0
[pid=29870] ppid=29869 vsize=63712 CPUtime=2.03
/proc/29870/stat : 29870 (minisatp_32) R 29869 29864 4778 34817 4778 4202496 22668 0 0 0 184 19 0 0 25 0 1 0 11256244 65241088 14236 1283457024 134512640 135413687 4288242784 18446744073709551615 134597339 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/29870/statm: 15928 14236 117 220 0 15706 0
Current children cumulated CPU time (s) 4.98
Current children cumulated vsize (KiB) 102172

[startup+5.11216 s]
/proc/loadavg: 1.27 1.41 1.35 2/37 29870
/proc/meminfo: memFree=182416/1048576 swapFree=0/0
[pid=29864] ppid=29863 vsize=2572 CPUtime=0
/proc/29864/stat : 29864 (packup2mp4pa-0.) S 29863 29864 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 25 0 1 0 11255946 2633728 275 1283457024 134512640 135304128 4290118992 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29864/statm: 643 275 233 194 0 30 0
[pid=29865] ppid=29864 vsize=31436 CPUtime=5.09
/proc/29865/stat : 29865 (packup) R 29864 29864 4778 34817 4778 4202496 15342 41713 0 0 109 23 339 38 18 0 1 0 11255946 32190464 7351 1283457024 134512640 134752139 4287945488 18446744073709551615 134555028 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/29865/statm: 7859 7351 345 59 0 7023 0
Current children cumulated CPU time (s) 5.09
Current children cumulated vsize (KiB) 34008

Child status: 0
Real time (s): 5.12494
CPU time (s): 5.12832
CPU user time (s): 4.48828
CPU system time (s): 0.64004
CPU usage (%): 100.066
Max. virtual memory (cumulated for all children) (KiB): 112984

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.48828
system time used= 0.64004
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 57498
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= 11
involuntary context switches= 108

runsolver used 0 second user time and 0 second system time

The end