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/201108300820/aspuncud-user-1.0/4e539b28-d46c-11df-8f4f-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//4e539b28-d46c-11df-8f4f-00163e3d3b7c.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/4e539b28-d46c-11df-8f4f-00163e3d3b7c.cudf.dudf-real.result +sum(installedsize) 

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.00 1.00 1.00 1/33 9163
/proc/meminfo: memFree=942480/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=3024 CPUtime=0
/proc/9163/stat : 9163 (runsolver) D 9162 9163 2160 34817 2160 4202560 73 0 0 0 0 0 0 0 25 0 1 0 54552583 3096576 94 1283457024 134512640 134586868 4293859312 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/9163/statm: 756 94 62 19 0 55 0

[startup+0.142037 s]
/proc/loadavg: 1.00 1.00 1.00 1/33 9163
/proc/meminfo: memFree=942480/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=0
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+0.20608 s]
/proc/loadavg: 1.00 1.00 1.00 1/33 9163
/proc/meminfo: memFree=942480/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=0
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+0.312307 s]
/proc/loadavg: 1.00 1.00 1.00 1/33 9163
/proc/meminfo: memFree=942480/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=0
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+0.712421 s]
/proc/loadavg: 1.00 1.00 1.00 1/33 9163
/proc/meminfo: memFree=942480/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=0
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+1.51265 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 9174
/proc/meminfo: memFree=914040/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=0
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
[pid=9172] ppid=9163 vsize=3444 CPUtime=0
/proc/9172/stat : 9172 (unclasp) S 9163 9163 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 25 0 1 0 54552588 3526656 272 1283457024 134512640 135121179 4291568832 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9172/statm: 861 272 240 149 0 52 0
[pid=9173] ppid=9163 vsize=2692 CPUtime=0
/proc/9173/stat : 9173 (gringo) S 9163 9163 2160 34817 2160 4202496 385 0 23 0 0 0 0 0 24 0 1 0 54552588 2756608 281 1283457024 134512640 137056543 4290570336 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9173/statm: 673 281 252 622 0 48 0
[pid=9174] ppid=9163 vsize=27644 CPUtime=1.3
/proc/9174/stat : 9174 (cudf2lp) R 9163 9163 2160 34817 2160 4202496 8067 0 15 0 129 1 0 0 25 0 1 0 54552588 28307456 6344 1283457024 134512640 135786343 4291565504 18446744073709551615 134625492 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9174/statm: 6911 6344 128 311 0 6598 0
Current children cumulated CPU time (s) 1.3
Current children cumulated vsize (KiB) 36368

[startup+3.1131 s]
/proc/loadavg: 1.00 1.00 1.00 3/37 9174
/proc/meminfo: memFree=888744/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=0
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
[pid=9172] ppid=9163 vsize=21356 CPUtime=0.08
/proc/9172/stat : 9172 (unclasp) S 9163 9163 2160 34817 2160 4202496 5582 0 6 0 6 2 0 0 18 0 1 0 54552588 21868544 4795 1283457024 134512640 135121179 4291568832 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9172/statm: 5339 4795 275 149 0 4530 0
[pid=9173] ppid=9163 vsize=31092 CPUtime=0.92
/proc/9173/stat : 9173 (gringo) R 9163 9163 2160 34817 2160 4202496 9295 0 23 0 90 2 0 0 18 0 1 0 54552588 31838208 5897 1283457024 134512640 137056543 4290570336 18446744073709551615 136268524 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9173/statm: 7773 5897 253 622 0 7148 0
[pid=9174] ppid=9163 vsize=36992 CPUtime=1.87
/proc/9174/stat : 9174 (cudf2lp) R 9163 9163 2160 34817 2160 4202496 11840 0 15 0 182 5 0 0 25 0 1 0 54552588 37879808 9052 1283457024 134512640 135786343 4291565504 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9174/statm: 9248 9052 139 311 0 8935 0
Current children cumulated CPU time (s) 2.87
Current children cumulated vsize (KiB) 92028

[startup+6.31391 s]
/proc/loadavg: 1.00 1.00 1.00 3/36 9174
/proc/meminfo: memFree=812880/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=2.24
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 13365 0 18 0 0 219 5 18 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
[pid=9172] ppid=9163 vsize=71508 CPUtime=0.64
/proc/9172/stat : 9172 (unclasp) R 9163 9163 2160 34817 2160 4202496 19511 0 6 0 58 6 0 0 18 0 1 0 54552588 73224192 17156 1283457024 134512640 135121179 4291568832 18446744073709551615 134695592 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9172/statm: 17877 17156 277 149 0 17068 0
[pid=9173] ppid=9163 vsize=116780 CPUtime=3.19
/proc/9173/stat : 9173 (gringo) R 9163 9163 2160 34817 2160 4202496 36152 0 23 0 309 10 0 0 19 0 1 0 54552588 119582720 23828 1283457024 134512640 137056543 4290570336 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9173/statm: 29195 23828 268 622 0 28570 0
Current children cumulated CPU time (s) 6.07
Current children cumulated vsize (KiB) 190876

[startup+12.7055 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 9174
/proc/meminfo: memFree=838876/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=6.12
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 53263 0 41 0 0 592 20 18 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
[pid=9172] ppid=9163 vsize=108028 CPUtime=6.35
/proc/9172/stat : 9172 (unclasp) R 9163 9163 2160 34817 2160 4202496 114890 0 7 0 589 46 0 0 25 0 1 0 54552588 110620672 25121 1283457024 134512640 135121179 4291568832 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9172/statm: 27007 25121 319 149 0 26198 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 110616

[startup+25.5091 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 9174
/proc/meminfo: memFree=839496/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=6.12
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 53263 0 41 0 0 592 20 18 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
[pid=9172] ppid=9163 vsize=105528 CPUtime=19.15
/proc/9172/stat : 9172 (unclasp) R 9163 9163 2160 34817 2160 4202496 333830 0 7 0 1782 133 0 0 25 0 1 0 54552588 108060672 24595 1283457024 134512640 135121179 4291568832 18446744073709551615 134734410 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9172/statm: 26382 24595 321 149 0 25573 0
Current children cumulated CPU time (s) 25.27
Current children cumulated vsize (KiB) 108116

[startup+51.1082 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 9174
/proc/meminfo: memFree=840612/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=6.12
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 53263 0 41 0 0 592 20 18 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
[pid=9172] ppid=9163 vsize=105964 CPUtime=44.74
/proc/9172/stat : 9172 (unclasp) R 9163 9163 2160 34817 2160 4202496 765072 0 7 0 4151 323 0 0 25 0 1 0 54552588 108507136 24625 1283457024 134512640 135121179 4291568832 18446744073709551615 4159132741 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9172/statm: 26491 24625 321 149 0 25682 0
Current children cumulated CPU time (s) 50.86
Current children cumulated vsize (KiB) 108552

[startup+102.305 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 9174
/proc/meminfo: memFree=840364/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=6.12
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 53263 0 41 0 0 592 20 18 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
[pid=9172] ppid=9163 vsize=105544 CPUtime=95.89
/proc/9172/stat : 9172 (unclasp) R 9163 9163 2160 34817 2160 4202496 1599480 0 7 0 8907 682 0 0 25 0 1 0 54552588 108077056 24542 1283457024 134512640 135121179 4291568832 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9172/statm: 26386 24542 321 149 0 25577 0
Current children cumulated CPU time (s) 102.01
Current children cumulated vsize (KiB) 108132

[startup+162.308 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 9174
/proc/meminfo: memFree=840116/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=6.12
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 53263 0 41 0 0 592 20 18 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
[pid=9172] ppid=9163 vsize=105556 CPUtime=155.82
/proc/9172/stat : 9172 (unclasp) R 9163 9163 2160 34817 2160 4202496 2546377 0 7 0 14514 1068 0 0 25 0 1 0 54552588 108089344 24564 1283457024 134512640 135121179 4291568832 18446744073709551615 134734358 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9172/statm: 26389 24564 321 149 0 25580 0
Current children cumulated CPU time (s) 161.94
Current children cumulated vsize (KiB) 108144

[startup+222.308 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 9180
/proc/meminfo: memFree=839844/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=6.12
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 53263 0 41 0 0 592 20 18 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
[pid=9172] ppid=9163 vsize=106004 CPUtime=215.75
/proc/9172/stat : 9172 (unclasp) R 9163 9163 2160 34817 2160 4202496 3484719 0 7 0 20110 1465 0 0 25 0 1 0 54552588 108548096 24697 1283457024 134512640 135121179 4291568832 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9172/statm: 26501 24697 321 149 0 25692 0
Current children cumulated CPU time (s) 221.87
Current children cumulated vsize (KiB) 108592

[startup+282.309 s]
/proc/loadavg: 1.00 1.00 1.00 2/36 9185
/proc/meminfo: memFree=838992/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=6.12
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 53263 0 41 0 0 592 20 18 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
[pid=9172] ppid=9163 vsize=106020 CPUtime=275.7
/proc/9172/stat : 9172 (unclasp) R 9163 9163 2160 34817 2160 4202496 4405171 0 7 0 25724 1846 0 0 25 0 1 0 54552588 108564480 24719 1283457024 134512640 135121179 4291568832 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9172/statm: 26505 24719 321 149 0 25696 0
Current children cumulated CPU time (s) 281.82
Current children cumulated vsize (KiB) 108608



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.512 s]
/proc/loadavg: 1.00 1.00 1.00 2/36 9185
/proc/meminfo: memFree=839116/1048576 swapFree=0/0
[pid=9163] ppid=9162 vsize=2588 CPUtime=6.12
/proc/9163/stat : 9163 (aspuncud-user-1) S 9162 9163 2160 34817 2160 4202496 568 53263 0 41 0 0 592 20 18 0 1 0 54552583 2650112 297 1283457024 134512640 135304128 4291038736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9163/statm: 647 297 251 194 0 34 0
[pid=9172] ppid=9163 vsize=106020 CPUtime=283.89
/proc/9172/stat : 9172 (unclasp) R 9163 9163 2160 34817 2160 4202496 4531267 0 7 0 26487 1902 0 0 25 0 1 0 54552588 108564480 24723 1283457024 134512640 135121179 4291568832 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9172/statm: 26505 24723 321 149 0 25696 0
Current children cumulated CPU time (s) 290.01
Current children cumulated vsize (KiB) 108608

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 290.558
CPU time (s): 290.046
CPU user time (s): 270.801
CPU system time (s): 19.2452
CPU usage (%): 99.8238
Max. virtual memory (cumulated for all children) (KiB): 210332

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 270.801
system time used= 19.2452
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 4587474
page faults= 50
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 7279
involuntary context switches= 9278

runsolver used 0 second user time and 0.004 second system time

The end