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/201108241238/aspuncud-trendy-1.3/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/dudf-real//6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/6b0d1da0-c730-11df-a7c5-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.18 1.14 1.11 4/35 26369
/proc/meminfo: memFree=365740/1048576 swapFree=0/0
[pid=26369] ppid=26368 vsize=2516 CPUtime=0.01
/proc/26369/stat : 26369 (aspuncud-trendy) R 26368 26369 1511 34817 1511 4194304 188 0 0 0 0 1 0 0 25 0 1 0 4823722 2576384 108 1283457024 134512640 135304128 4291989264 18446744073709551615 4159095600 0 0 0 0 0 0 0 17 0 0 0 0
/proc/26369/statm: 629 108 88 194 0 16 0

[startup+0.200908 s]
/proc/loadavg: 1.18 1.14 1.11 4/35 26369
/proc/meminfo: memFree=365740/1048576 swapFree=0/0
[pid=26369] ppid=26368 vsize=2592 CPUtime=0.01
/proc/26369/stat : 26369 (aspuncud-trendy) S 26368 26369 1511 34817 1511 4202496 617 2230 0 0 0 1 0 0 25 0 1 0 4823722 2654208 298 1283457024 134512640 135304128 4291989264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26369/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.30488 s]
/proc/loadavg: 1.18 1.14 1.11 4/35 26369
/proc/meminfo: memFree=365740/1048576 swapFree=0/0
[pid=26369] ppid=26368 vsize=2592 CPUtime=0.01
/proc/26369/stat : 26369 (aspuncud-trendy) S 26368 26369 1511 34817 1511 4202496 617 2230 0 0 0 1 0 0 25 0 1 0 4823722 2654208 298 1283457024 134512640 135304128 4291989264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26369/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.411154 s]
/proc/loadavg: 1.18 1.14 1.11 4/35 26369
/proc/meminfo: memFree=365740/1048576 swapFree=0/0
[pid=26369] ppid=26368 vsize=2592 CPUtime=0.01
/proc/26369/stat : 26369 (aspuncud-trendy) S 26368 26369 1511 34817 1511 4202496 617 2230 0 0 0 1 0 0 25 0 1 0 4823722 2654208 298 1283457024 134512640 135304128 4291989264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26369/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.704903 s]
/proc/loadavg: 1.18 1.14 1.11 4/35 26369
/proc/meminfo: memFree=365740/1048576 swapFree=0/0
[pid=26369] ppid=26368 vsize=2592 CPUtime=0.01
/proc/26369/stat : 26369 (aspuncud-trendy) S 26368 26369 1511 34817 1511 4202496 617 2230 0 0 0 1 0 0 25 0 1 0 4823722 2654208 298 1283457024 134512640 135304128 4291989264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26369/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.50495 s]
/proc/loadavg: 1.17 1.14 1.11 2/39 26383
/proc/meminfo: memFree=325712/1048576 swapFree=0/0
[pid=26369] ppid=26368 vsize=2592 CPUtime=0.01
/proc/26369/stat : 26369 (aspuncud-trendy) S 26368 26369 1511 34817 1511 4202496 617 2230 0 0 0 1 0 0 25 0 1 0 4823722 2654208 298 1283457024 134512640 135304128 4291989264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26369/statm: 648 298 251 194 0 35 0
[pid=26381] ppid=26369 vsize=3448 CPUtime=0
/proc/26381/stat : 26381 (unclasp) S 26369 26369 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 4823723 3530752 272 1283457024 134512640 135121179 4290684496 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/26381/statm: 862 272 240 149 0 53 0
[pid=26382] ppid=26369 vsize=2692 CPUtime=0
/proc/26382/stat : 26382 (gringo) S 26369 26369 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 4823723 2756608 281 1283457024 134512640 137056543 4294242624 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/26382/statm: 673 281 252 622 0 48 0
[pid=26383] ppid=26369 vsize=26316 CPUtime=1.33
/proc/26383/stat : 26383 (cudf2lp) R 26369 26369 1511 34817 1511 4202496 7870 0 0 0 126 7 0 0 25 0 1 0 4823724 26947584 6132 1283457024 134512640 135786343 4292733008 18446744073709551615 134924413 0 0 6 0 0 0 0 17 0 0 0 0
/proc/26383/statm: 6579 6132 126 311 0 6266 0
Current children cumulated CPU time (s) 1.34
Current children cumulated vsize (KiB) 35048

[startup+3.10254 s]
/proc/loadavg: 1.17 1.14 1.11 2/39 26383
/proc/meminfo: memFree=289968/1048576 swapFree=0/0
[pid=26369] ppid=26368 vsize=2592 CPUtime=1.85
/proc/26369/stat : 26369 (aspuncud-trendy) S 26368 26369 1511 34817 1511 4202496 617 14451 0 0 0 1 174 10 18 0 1 0 4823722 2654208 298 1283457024 134512640 135304128 4291989264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26369/statm: 648 298 251 194 0 35 0
[pid=26381] ppid=26369 vsize=25396 CPUtime=0.16
/proc/26381/stat : 26381 (unclasp) R 26369 26369 1511 34817 1511 4202496 6423 0 0 0 12 4 0 0 18 0 1 0 4823723 26005504 5766 1283457024 134512640 135121179 4290684496 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/26381/statm: 6349 5766 277 149 0 5540 0
[pid=26382] ppid=26369 vsize=34780 CPUtime=0.91
/proc/26382/stat : 26382 (gringo) R 26369 26369 1511 34817 1511 4202496 9429 0 0 0 88 3 0 0 18 0 1 0 4823723 35614720 7339 1283457024 134512640 137056543 4294242624 18446744073709551615 134890274 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/26382/statm: 8695 7339 268 622 0 8070 0
Current children cumulated CPU time (s) 2.92
Current children cumulated vsize (KiB) 62768

[startup+6.3134 s]
/proc/loadavg: 1.17 1.14 1.11 2/37 26384
/proc/meminfo: memFree=309840/1048576 swapFree=0/0
[pid=26369] ppid=26368 vsize=2592 CPUtime=2.85
/proc/26369/stat : 26369 (aspuncud-trendy) S 26368 26369 1511 34817 1511 4202496 617 23970 0 0 0 1 269 15 15 0 1 0 4823722 2654208 298 1283457024 134512640 135304128 4291989264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26369/statm: 648 298 251 194 0 35 0
[pid=26381] ppid=26369 vsize=38432 CPUtime=3.3
/proc/26381/stat : 26381 (unclasp) R 26369 26369 1511 34817 1511 4202496 34396 0 0 0 317 13 0 0 25 0 1 0 4823723 39354368 8642 1283457024 134512640 135121179 4290684496 18446744073709551615 134869284 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/26381/statm: 9608 8642 331 149 0 8799 0
Current children cumulated CPU time (s) 6.15
Current children cumulated vsize (KiB) 41024

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

[startup+6.51345 s]
/proc/loadavg: 1.17 1.14 1.11 2/37 26384
/proc/meminfo: memFree=309840/1048576 swapFree=0/0
[pid=26369] ppid=26368 vsize=2592 CPUtime=2.85
/proc/26369/stat : 26369 (aspuncud-trendy) S 26368 26369 1511 34817 1511 4202496 617 23970 0 0 0 1 269 15 15 0 1 0 4823722 2654208 298 1283457024 134512640 135304128 4291989264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26369/statm: 648 298 251 194 0 35 0
[pid=26381] ppid=26369 vsize=38432 CPUtime=3.5
/proc/26381/stat : 26381 (unclasp) R 26369 26369 1511 34817 1511 4202496 35860 0 0 0 337 13 0 0 25 0 1 0 4823723 39354368 8642 1283457024 134512640 135121179 4290684496 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/26381/statm: 9608 8642 331 149 0 8799 0
Current children cumulated CPU time (s) 6.35
Current children cumulated vsize (KiB) 41024

[startup+9.71456 s]
/proc/loadavg: 1.16 1.13 1.11 2/37 26384
/proc/meminfo: memFree=308980/1048576 swapFree=0/0
[pid=26369] ppid=26368 vsize=2592 CPUtime=2.85
/proc/26369/stat : 26369 (aspuncud-trendy) S 26368 26369 1511 34817 1511 4202496 617 23970 0 0 0 1 269 15 15 0 1 0 4823722 2654208 298 1283457024 134512640 135304128 4291989264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26369/statm: 648 298 251 194 0 35 0
[pid=26381] ppid=26369 vsize=37892 CPUtime=6.69
/proc/26381/stat : 26381 (unclasp) R 26369 26369 1511 34817 1511 4202496 51951 0 0 0 648 21 0 0 25 0 1 0 4823723 38801408 8541 1283457024 134512640 135121179 4290684496 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/26381/statm: 9473 8541 333 149 0 8664 0
Current children cumulated CPU time (s) 9.54
Current children cumulated vsize (KiB) 40484

[startup+10.5149 s]
/proc/loadavg: 1.16 1.13 1.11 2/37 26384
/proc/meminfo: memFree=308980/1048576 swapFree=0/0
[pid=26369] ppid=26368 vsize=2592 CPUtime=2.85
/proc/26369/stat : 26369 (aspuncud-trendy) S 26368 26369 1511 34817 1511 4202496 617 23970 0 0 0 1 269 15 15 0 1 0 4823722 2654208 298 1283457024 134512640 135304128 4291989264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26369/statm: 648 298 251 194 0 35 0
[pid=26381] ppid=26369 vsize=38440 CPUtime=7.49
/proc/26381/stat : 26381 (unclasp) R 26369 26369 1511 34817 1511 4202496 56887 0 0 0 725 24 0 0 25 0 1 0 4823723 39362560 8678 1283457024 134512640 135121179 4290684496 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/26381/statm: 9610 8678 333 149 0 8801 0
Current children cumulated CPU time (s) 10.34
Current children cumulated vsize (KiB) 41032

[startup+10.9151 s]
/proc/loadavg: 1.16 1.13 1.11 2/37 26384
/proc/meminfo: memFree=308980/1048576 swapFree=0/0
[pid=26369] ppid=26368 vsize=2592 CPUtime=2.85
/proc/26369/stat : 26369 (aspuncud-trendy) S 26368 26369 1511 34817 1511 4202496 617 23970 0 0 0 1 269 15 15 0 1 0 4823722 2654208 298 1283457024 134512640 135304128 4291989264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26369/statm: 648 298 251 194 0 35 0
[pid=26381] ppid=26369 vsize=37708 CPUtime=7.9
/proc/26381/stat : 26381 (unclasp) R 26369 26369 1511 34817 1511 4202496 62461 0 0 0 762 28 0 0 25 0 1 0 4823723 38612992 8495 1283457024 134512640 135121179 4290684496 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/26381/statm: 9427 8495 333 149 0 8618 0
Current children cumulated CPU time (s) 10.75
Current children cumulated vsize (KiB) 40300

[startup+11.3152 s]
/proc/loadavg: 1.14 1.13 1.11 2/37 26384
/proc/meminfo: memFree=309972/1048576 swapFree=0/0
[pid=26369] ppid=26368 vsize=2592 CPUtime=2.85
/proc/26369/stat : 26369 (aspuncud-trendy) S 26368 26369 1511 34817 1511 4202496 617 23970 0 0 0 1 269 15 15 0 1 0 4823722 2654208 298 1283457024 134512640 135304128 4291989264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26369/statm: 648 298 251 194 0 35 0
[pid=26381] ppid=26369 vsize=38672 CPUtime=8.29
/proc/26381/stat : 26381 (unclasp) R 26369 26369 1511 34817 1511 4202496 68734 0 0 0 801 28 0 0 25 0 1 0 4823723 39600128 8681 1283457024 134512640 135121179 4290684496 18446744073709551615 134649504 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/26381/statm: 9668 8681 333 149 0 8859 0
Current children cumulated CPU time (s) 11.14
Current children cumulated vsize (KiB) 41264

Child status: 0
Real time (s): 11.3729
CPU time (s): 11.2127
CPU user time (s): 10.7367
CPU system time (s): 0.476029
CPU usage (%): 98.5916
Max. virtual memory (cumulated for all children) (KiB): 71460

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 10.7367
system time used= 0.476029
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 95949
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= 1709
involuntary context switches= 1420

runsolver used 0 second user time and 0 second system time

The end