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/dd08e73e-d489-11df-b9cf-00163e3d3b7c.cudf.dudf-real.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-real//dd08e73e-d489-11df-b9cf-00163e3d3b7c.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/dd08e73e-d489-11df-b9cf-00163e3d3b7c.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.50 1.49 1.37 4/35 29337
/proc/meminfo: memFree=286796/1048576 swapFree=0/0
[pid=29336] ppid=29335 vsize=2568 CPUtime=0
/proc/29336/stat : 29336 (packup2mp4pa-0.) S 29335 29336 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11249896 2629632 273 1283457024 134512640 135304128 4290760176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29336/statm: 642 273 233 194 0 29 0
[pid=29337] ppid=29336 vsize=3712 CPUtime=0
/proc/29337/stat : 29337 (packup) R 29336 29336 4778 34817 4778 4202496 412 0 0 0 0 0 0 0 25 0 1 0 11249896 3801088 341 1283457024 134512640 134752139 4287488672 18446744073709551615 134681635 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/29337/statm: 928 341 286 59 0 92 0

[startup+0.134202 s]
/proc/loadavg: 1.50 1.49 1.37 4/35 29337
/proc/meminfo: memFree=286796/1048576 swapFree=0/0
[pid=29336] ppid=29335 vsize=2568 CPUtime=0
/proc/29336/stat : 29336 (packup2mp4pa-0.) S 29335 29336 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11249896 2629632 273 1283457024 134512640 135304128 4290760176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29336/statm: 642 273 233 194 0 29 0
[pid=29337] ppid=29336 vsize=8376 CPUtime=0.14
/proc/29337/stat : 29337 (packup) R 29336 29336 4778 34817 4778 4202496 1574 0 0 0 14 0 0 0 25 0 1 0 11249896 8577024 1503 1283457024 134512640 134752139 4287488672 18446744073709551615 134682079 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/29337/statm: 2094 1503 286 59 0 1258 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 10944

[startup+0.204213 s]
/proc/loadavg: 1.50 1.49 1.37 4/35 29337
/proc/meminfo: memFree=286796/1048576 swapFree=0/0
[pid=29336] ppid=29335 vsize=2568 CPUtime=0
/proc/29336/stat : 29336 (packup2mp4pa-0.) S 29335 29336 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11249896 2629632 273 1283457024 134512640 135304128 4290760176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29336/statm: 642 273 233 194 0 29 0
[pid=29337] ppid=29336 vsize=10488 CPUtime=0.2
/proc/29337/stat : 29337 (packup) R 29336 29336 4778 34817 4778 4202496 2109 0 0 0 20 0 0 0 25 0 1 0 11249896 10739712 2038 1283457024 134512640 134752139 4287488672 18446744073709551615 4157715171 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/29337/statm: 2622 2038 286 59 0 1786 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13056

[startup+0.304227 s]
/proc/loadavg: 1.50 1.49 1.37 4/35 29337
/proc/meminfo: memFree=286796/1048576 swapFree=0/0
[pid=29336] ppid=29335 vsize=2568 CPUtime=0
/proc/29336/stat : 29336 (packup2mp4pa-0.) S 29335 29336 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11249896 2629632 273 1283457024 134512640 135304128 4290760176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29336/statm: 642 273 233 194 0 29 0
[pid=29337] ppid=29336 vsize=13340 CPUtime=0.3
/proc/29337/stat : 29337 (packup) R 29336 29336 4778 34817 4778 4202496 2823 0 0 0 30 0 0 0 25 0 1 0 11249896 13660160 2752 1283457024 134512640 134752139 4287488672 18446744073709551615 4157649903 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/29337/statm: 3335 2752 286 59 0 2499 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15908

[startup+0.704287 s]
/proc/loadavg: 1.50 1.49 1.37 4/35 29337
/proc/meminfo: memFree=286796/1048576 swapFree=0/0
[pid=29336] ppid=29335 vsize=2568 CPUtime=0
/proc/29336/stat : 29336 (packup2mp4pa-0.) S 29335 29336 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11249896 2629632 273 1283457024 134512640 135304128 4290760176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29336/statm: 642 273 233 194 0 29 0
[pid=29337] ppid=29336 vsize=23444 CPUtime=0.7
/proc/29337/stat : 29337 (packup) R 29336 29336 4778 34817 4778 4202496 5338 0 0 0 68 2 0 0 25 0 1 0 11249896 24006656 5267 1283457024 134512640 134752139 4287488672 18446744073709551615 4159655108 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/29337/statm: 5861 5267 286 59 0 5025 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 26012

[startup+1.5044 s]
/proc/loadavg: 1.50 1.49 1.37 2/36 29338
/proc/meminfo: memFree=252808/1048576 swapFree=0/0
[pid=29336] ppid=29335 vsize=2568 CPUtime=0
/proc/29336/stat : 29336 (packup2mp4pa-0.) S 29335 29336 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11249896 2629632 273 1283457024 134512640 135304128 4290760176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29336/statm: 642 273 233 194 0 29 0
[pid=29337] ppid=29336 vsize=42188 CPUtime=1.4
/proc/29337/stat : 29337 (packup) S 29336 29336 4778 34817 4778 4202496 10170 0 0 0 126 14 0 0 25 0 1 0 11249896 43200512 9832 1283457024 134512640 134752139 4287488672 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/29337/statm: 10547 9832 324 59 0 9711 0
Current children cumulated CPU time (s) 1.4
Current children cumulated vsize (KiB) 44756

[startup+3.10462 s]
/proc/loadavg: 1.50 1.49 1.37 2/38 29340
/proc/meminfo: memFree=229712/1048576 swapFree=0/0
[pid=29336] ppid=29335 vsize=2568 CPUtime=0
/proc/29336/stat : 29336 (packup2mp4pa-0.) S 29335 29336 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11249896 2629632 273 1283457024 134512640 135304128 4290760176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29336/statm: 642 273 233 194 0 29 0
[pid=29337] ppid=29336 vsize=42188 CPUtime=1.4
/proc/29337/stat : 29337 (packup) S 29336 29336 4778 34817 4778 4202496 10170 0 0 0 126 14 0 0 25 0 1 0 11249896 43200512 9832 1283457024 134512640 134752139 4287488672 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/29337/statm: 10547 9832 324 59 0 9711 0
[pid=29339] ppid=29337 vsize=1672 CPUtime=0.01
/proc/29339/stat : 29339 (sh) S 29337 29336 4778 34817 4778 4202496 147 0 0 0 0 1 0 0 25 0 1 0 11250036 1712128 124 1283457024 134512640 134593992 4293273856 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/29339/statm: 418 124 108 20 0 45 0
[pid=29340] ppid=29339 vsize=66380 CPUtime=1.68
/proc/29340/stat : 29340 (minisatp_32) R 29339 29336 4778 34817 4778 4202496 20542 0 0 0 150 18 0 0 25 0 1 0 11250037 67973120 15500 1283457024 134512640 135413687 4292325440 18446744073709551615 134688782 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/29340/statm: 16595 15500 107 220 0 16373 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 112808

[startup+6.30572 s]
/proc/loadavg: 1.46 1.48 1.37 2/38 29342
/proc/meminfo: memFree=227356/1048576 swapFree=0/0
[pid=29336] ppid=29335 vsize=2568 CPUtime=0
/proc/29336/stat : 29336 (packup2mp4pa-0.) S 29335 29336 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11249896 2629632 273 1283457024 134512640 135304128 4290760176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29336/statm: 642 273 233 194 0 29 0
[pid=29337] ppid=29336 vsize=42192 CPUtime=4.49
/proc/29337/stat : 29337 (packup) S 29336 29336 4778 34817 4778 4202496 10251 27404 0 0 137 28 263 21 18 0 1 0 11249896 43204608 9841 1283457024 134512640 134752139 4287488672 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/29337/statm: 10548 9841 332 59 0 9712 0
[pid=29341] ppid=29337 vsize=1672 CPUtime=0
/proc/29341/stat : 29341 (sh) S 29337 29336 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11250347 1712128 123 1283457024 134512640 134593992 4288482416 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/29341/statm: 418 123 108 20 0 45 0
[pid=29342] ppid=29341 vsize=89224 CPUtime=1.79
/proc/29342/stat : 29342 (minisatp_32) R 29341 29336 4778 34817 4778 4202496 24755 0 0 0 165 14 0 0 25 0 1 0 11250347 91365376 19664 1283457024 134512640 135413687 4290741952 18446744073709551615 134689208 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/29342/statm: 22306 19664 108 220 0 22084 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 135656

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

[startup+6.40575 s]
/proc/loadavg: 1.46 1.48 1.37 2/38 29342
/proc/meminfo: memFree=227356/1048576 swapFree=0/0
[pid=29336] ppid=29335 vsize=2568 CPUtime=0
/proc/29336/stat : 29336 (packup2mp4pa-0.) S 29335 29336 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11249896 2629632 273 1283457024 134512640 135304128 4290760176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29336/statm: 642 273 233 194 0 29 0
[pid=29337] ppid=29336 vsize=42192 CPUtime=4.49
/proc/29337/stat : 29337 (packup) S 29336 29336 4778 34817 4778 4202496 10251 27404 0 0 137 28 263 21 18 0 1 0 11249896 43204608 9841 1283457024 134512640 134752139 4287488672 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/29337/statm: 10548 9841 332 59 0 9712 0
[pid=29341] ppid=29337 vsize=1672 CPUtime=0
/proc/29341/stat : 29341 (sh) S 29337 29336 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11250347 1712128 123 1283457024 134512640 134593992 4288482416 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/29341/statm: 418 123 108 20 0 45 0
[pid=29342] ppid=29341 vsize=92648 CPUtime=1.89
/proc/29342/stat : 29342 (minisatp_32) R 29341 29336 4778 34817 4778 4202496 25734 0 0 0 175 14 0 0 25 0 1 0 11250347 94871552 20616 1283457024 134512640 135413687 4290741952 18446744073709551615 134686432 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/29342/statm: 23162 20616 108 220 0 22940 0
Current children cumulated CPU time (s) 6.38
Current children cumulated vsize (KiB) 139080

[startup+7.20609 s]
/proc/loadavg: 1.46 1.48 1.37 2/38 29342
/proc/meminfo: memFree=158288/1048576 swapFree=0/0
[pid=29336] ppid=29335 vsize=2568 CPUtime=0
/proc/29336/stat : 29336 (packup2mp4pa-0.) S 29335 29336 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11249896 2629632 273 1283457024 134512640 135304128 4290760176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29336/statm: 642 273 233 194 0 29 0
[pid=29337] ppid=29336 vsize=42192 CPUtime=4.49
/proc/29337/stat : 29337 (packup) S 29336 29336 4778 34817 4778 4202496 10251 27404 0 0 137 28 263 21 18 0 1 0 11249896 43204608 9841 1283457024 134512640 134752139 4287488672 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/29337/statm: 10548 9841 332 59 0 9712 0
[pid=29341] ppid=29337 vsize=1672 CPUtime=0
/proc/29341/stat : 29341 (sh) S 29337 29336 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11250347 1712128 123 1283457024 134512640 134593992 4288482416 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/29341/statm: 418 123 108 20 0 45 0
[pid=29342] ppid=29341 vsize=102304 CPUtime=2.69
/proc/29342/stat : 29342 (minisatp_32) R 29341 29336 4778 34817 4778 4202496 30722 0 0 0 251 18 0 0 25 0 1 0 11250347 104759296 23020 1283457024 134512640 135413687 4290741952 18446744073709551615 134688839 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/29342/statm: 25576 23020 108 220 0 25354 0
Current children cumulated CPU time (s) 7.18
Current children cumulated vsize (KiB) 148736

[startup+8.00627 s]
/proc/loadavg: 1.46 1.48 1.37 2/38 29342
/proc/meminfo: memFree=156808/1048576 swapFree=0/0
[pid=29336] ppid=29335 vsize=2568 CPUtime=0
/proc/29336/stat : 29336 (packup2mp4pa-0.) S 29335 29336 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11249896 2629632 273 1283457024 134512640 135304128 4290760176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29336/statm: 642 273 233 194 0 29 0
[pid=29337] ppid=29336 vsize=42192 CPUtime=4.49
/proc/29337/stat : 29337 (packup) S 29336 29336 4778 34817 4778 4202496 10251 27404 0 0 137 28 263 21 18 0 1 0 11249896 43204608 9841 1283457024 134512640 134752139 4287488672 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/29337/statm: 10548 9841 332 59 0 9712 0
[pid=29341] ppid=29337 vsize=1672 CPUtime=0
/proc/29341/stat : 29341 (sh) S 29337 29336 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11250347 1712128 123 1283457024 134512640 134593992 4288482416 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/29341/statm: 418 123 108 20 0 45 0
[pid=29342] ppid=29341 vsize=112340 CPUtime=3.49
/proc/29342/stat : 29342 (minisatp_32) R 29341 29336 4778 34817 4778 4202496 34998 0 0 0 326 23 0 0 25 0 1 0 11250347 115036160 24402 1283457024 134512640 135413687 4290741952 18446744073709551615 134692025 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/29342/statm: 28085 24402 108 220 0 27863 0
Current children cumulated CPU time (s) 7.98
Current children cumulated vsize (KiB) 158772

[startup+8.40646 s]
/proc/loadavg: 1.46 1.48 1.37 2/38 29342
/proc/meminfo: memFree=156808/1048576 swapFree=0/0
[pid=29336] ppid=29335 vsize=2568 CPUtime=0
/proc/29336/stat : 29336 (packup2mp4pa-0.) S 29335 29336 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11249896 2629632 273 1283457024 134512640 135304128 4290760176 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/29336/statm: 642 273 233 194 0 29 0
[pid=29337] ppid=29336 vsize=42196 CPUtime=8.38
/proc/29337/stat : 29337 (packup) R 29336 29336 4778 34817 4778 4202496 10341 63964 0 0 140 29 621 48 18 0 1 0 11249896 43208704 9855 1283457024 134512640 134752139 4287488672 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/29337/statm: 10549 9855 345 59 0 9713 0
Current children cumulated CPU time (s) 8.38
Current children cumulated vsize (KiB) 44764

Child status: 0
Real time (s): 8.50401
CPU time (s): 8.48853
CPU user time (s): 7.68848
CPU system time (s): 0.80005
CPU usage (%): 99.818
Max. virtual memory (cumulated for all children) (KiB): 167672

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.68848
system time used= 0.80005
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 83643
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= 141

runsolver used 0 second user time and 0 second system time

The end