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/rand192.cudf.dudf-random.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/dudf-random//rand192.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand192.cudf.dudf-random.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: 0.08 0.02 0.01 1/37 1523
/proc/meminfo: memFree=893172/1048576 swapFree=0/0
[pid=1523] ppid=1522 vsize=3020 CPUtime=0
/proc/1523/stat : 1523 (runsolver) D 1522 1523 1511 34817 1511 4202560 72 0 0 0 0 0 0 0 25 0 1 0 558063 3092480 94 1283457024 134512640 134586868 4293967968 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/1523/statm: 755 94 62 19 0 54 0

[startup+0.14642 s]
/proc/loadavg: 0.08 0.02 0.01 1/37 1523
/proc/meminfo: memFree=893172/1048576 swapFree=0/0
[pid=1523] ppid=1522 vsize=2596 CPUtime=0
/proc/1523/stat : 1523 (aspuncud-trendy) S 1522 1523 1511 34817 1511 4202496 624 2226 0 2 0 0 0 0 25 0 1 0 558063 2658304 298 1283457024 134512640 135304128 4291946304 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1523/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.20642 s]
/proc/loadavg: 0.08 0.02 0.01 1/37 1523
/proc/meminfo: memFree=893172/1048576 swapFree=0/0
[pid=1523] ppid=1522 vsize=2596 CPUtime=0
/proc/1523/stat : 1523 (aspuncud-trendy) S 1522 1523 1511 34817 1511 4202496 624 2226 0 2 0 0 0 0 25 0 1 0 558063 2658304 298 1283457024 134512640 135304128 4291946304 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1523/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.306385 s]
/proc/loadavg: 0.08 0.02 0.01 1/37 1523
/proc/meminfo: memFree=893172/1048576 swapFree=0/0
[pid=1523] ppid=1522 vsize=2596 CPUtime=0
/proc/1523/stat : 1523 (aspuncud-trendy) S 1522 1523 1511 34817 1511 4202496 624 2226 0 2 0 0 0 0 25 0 1 0 558063 2658304 298 1283457024 134512640 135304128 4291946304 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1523/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.706415 s]
/proc/loadavg: 0.08 0.02 0.01 1/37 1523
/proc/meminfo: memFree=893172/1048576 swapFree=0/0
[pid=1523] ppid=1522 vsize=2596 CPUtime=0
/proc/1523/stat : 1523 (aspuncud-trendy) S 1522 1523 1511 34817 1511 4202496 624 2226 0 2 0 0 0 0 25 0 1 0 558063 2658304 298 1283457024 134512640 135304128 4291946304 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1523/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50647 s]
/proc/loadavg: 0.08 0.02 0.01 2/41 1537
/proc/meminfo: memFree=864368/1048576 swapFree=0/0
[pid=1523] ppid=1522 vsize=2596 CPUtime=0
/proc/1523/stat : 1523 (aspuncud-trendy) S 1522 1523 1511 34817 1511 4202496 624 2226 0 2 0 0 0 0 25 0 1 0 558063 2658304 298 1283457024 134512640 135304128 4291946304 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1523/statm: 649 298 251 194 0 36 0
[pid=1535] ppid=1523 vsize=3448 CPUtime=0
/proc/1535/stat : 1535 (unclasp) S 1523 1523 1511 34817 1511 4202496 402 0 6 0 0 0 0 0 24 0 1 0 558066 3530752 272 1283457024 134512640 135121179 4290414896 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/1535/statm: 862 272 240 149 0 53 0
[pid=1536] ppid=1523 vsize=2696 CPUtime=0
/proc/1536/stat : 1536 (gringo) S 1523 1523 1511 34817 1511 4202496 386 0 22 0 0 0 0 0 22 0 1 0 558066 2760704 281 1283457024 134512640 137056543 4290690240 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/1536/statm: 674 281 252 622 0 49 0
[pid=1537] ppid=1523 vsize=25004 CPUtime=1.05
/proc/1537/stat : 1537 (cudf2lp) R 1523 1523 1511 34817 1511 4202496 6975 0 15 0 103 2 0 0 25 0 1 0 558066 25604096 5397 1283457024 134512640 135786343 4293418608 18446744073709551615 134696384 0 0 6 0 0 0 0 17 0 0 0 0
/proc/1537/statm: 6251 5397 126 311 0 5938 0
Current children cumulated CPU time (s) 1.05
Current children cumulated vsize (KiB) 33744

[startup+3.10438 s]
/proc/loadavg: 0.08 0.02 0.01 2/41 1537
/proc/meminfo: memFree=835872/1048576 swapFree=0/0
[pid=1523] ppid=1522 vsize=2596 CPUtime=0
/proc/1523/stat : 1523 (aspuncud-trendy) S 1522 1523 1511 34817 1511 4202496 624 2226 0 2 0 0 0 0 25 0 1 0 558063 2658304 298 1283457024 134512640 135304128 4291946304 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1523/statm: 649 298 251 194 0 36 0
[pid=1535] ppid=1523 vsize=11952 CPUtime=0.01
/proc/1535/stat : 1535 (unclasp) S 1523 1523 1511 34817 1511 4202496 2874 0 7 0 0 1 0 0 18 0 1 0 558066 12238848 2359 1283457024 134512640 135121179 4290414896 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/1535/statm: 2988 2359 275 149 0 2179 0
[pid=1536] ppid=1523 vsize=15556 CPUtime=0.45
/proc/1536/stat : 1536 (gringo) R 1523 1523 1511 34817 1511 4202496 4331 0 22 0 43 2 0 0 18 0 1 0 558066 15929344 2826 1283457024 134512640 137056543 4290690240 18446744073709551615 134751440 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/1536/statm: 3889 2826 253 622 0 3264 0
[pid=1537] ppid=1523 vsize=40940 CPUtime=2.09
/proc/1537/stat : 1537 (cudf2lp) R 1523 1523 1511 34817 1511 4202496 12881 0 15 0 204 5 0 0 25 0 1 0 558066 41922560 10033 1283457024 134512640 135786343 4293418608 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/1537/statm: 10235 10033 137 311 0 9922 0
Current children cumulated CPU time (s) 2.55
Current children cumulated vsize (KiB) 71044

[startup+6.30671 s]
/proc/loadavg: 0.23 0.05 0.02 2/39 1537
/proc/meminfo: memFree=832196/1048576 swapFree=0/0
[pid=1523] ppid=1522 vsize=2596 CPUtime=3.11
/proc/1523/stat : 1523 (aspuncud-trendy) S 1522 1523 1511 34817 1511 4202496 624 23861 0 39 0 0 302 9 15 0 1 0 558063 2658304 298 1283457024 134512640 135304128 4291946304 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1523/statm: 649 298 251 194 0 36 0
[pid=1535] ppid=1523 vsize=33128 CPUtime=2.63
/proc/1535/stat : 1535 (unclasp) R 1523 1523 1511 34817 1511 4202496 26376 0 10 0 252 11 0 0 22 0 1 0 558066 33923072 7343 1283457024 134512640 135121179 4290414896 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/1535/statm: 8282 7343 333 149 0 7473 0
Current children cumulated CPU time (s) 5.74
Current children cumulated vsize (KiB) 35724

[startup+12.7095 s]
/proc/loadavg: 0.29 0.06 0.02 2/39 1537
/proc/meminfo: memFree=831948/1048576 swapFree=0/0
[pid=1523] ppid=1522 vsize=2596 CPUtime=3.11
/proc/1523/stat : 1523 (aspuncud-trendy) S 1522 1523 1511 34817 1511 4202496 624 23861 0 39 0 0 302 9 15 0 1 0 558063 2658304 298 1283457024 134512640 135304128 4291946304 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1523/statm: 649 298 251 194 0 36 0
[pid=1535] ppid=1523 vsize=33476 CPUtime=9.03
/proc/1535/stat : 1535 (unclasp) R 1523 1523 1511 34817 1511 4202496 78259 0 10 0 862 41 0 0 25 0 1 0 558066 34279424 7430 1283457024 134512640 135121179 4290414896 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/1535/statm: 8369 7430 333 149 0 7560 0
Current children cumulated CPU time (s) 12.14
Current children cumulated vsize (KiB) 36072

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

[startup+12.8095 s]
/proc/loadavg: 0.29 0.06 0.02 2/39 1537
/proc/meminfo: memFree=831948/1048576 swapFree=0/0
[pid=1523] ppid=1522 vsize=2596 CPUtime=3.11
/proc/1523/stat : 1523 (aspuncud-trendy) S 1522 1523 1511 34817 1511 4202496 624 23861 0 39 0 0 302 9 15 0 1 0 558063 2658304 298 1283457024 134512640 135304128 4291946304 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1523/statm: 649 298 251 194 0 36 0
[pid=1535] ppid=1523 vsize=33476 CPUtime=9.13
/proc/1535/stat : 1535 (unclasp) R 1523 1523 1511 34817 1511 4202496 78748 0 10 0 872 41 0 0 25 0 1 0 558066 34279424 7430 1283457024 134512640 135121179 4290414896 18446744073709551615 134643472 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/1535/statm: 8369 7430 333 149 0 7560 0
Current children cumulated CPU time (s) 12.24
Current children cumulated vsize (KiB) 36072

[startup+13.6098 s]
/proc/loadavg: 0.29 0.06 0.02 2/39 1537
/proc/meminfo: memFree=831576/1048576 swapFree=0/0
[pid=1523] ppid=1522 vsize=2596 CPUtime=3.11
/proc/1523/stat : 1523 (aspuncud-trendy) S 1522 1523 1511 34817 1511 4202496 624 23861 0 39 0 0 302 9 15 0 1 0 558063 2658304 298 1283457024 134512640 135304128 4291946304 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1523/statm: 649 298 251 194 0 36 0
[pid=1535] ppid=1523 vsize=33476 CPUtime=9.93
/proc/1535/stat : 1535 (unclasp) R 1523 1523 1511 34817 1511 4202496 84942 0 10 0 946 47 0 0 25 0 1 0 558066 34279424 7430 1283457024 134512640 135121179 4290414896 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/1535/statm: 8369 7430 333 149 0 7560 0
Current children cumulated CPU time (s) 13.04
Current children cumulated vsize (KiB) 36072

[startup+14.41 s]
/proc/loadavg: 0.29 0.06 0.02 2/38 1537
/proc/meminfo: memFree=832212/1048576 swapFree=0/0
[pid=1523] ppid=1522 vsize=2596 CPUtime=3.11
/proc/1523/stat : 1523 (aspuncud-trendy) S 1522 1523 1511 34817 1511 4202496 624 23861 0 39 0 0 302 9 15 0 1 0 558063 2658304 298 1283457024 134512640 135304128 4291946304 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1523/statm: 649 298 251 194 0 36 0
[pid=1535] ppid=1523 vsize=33276 CPUtime=10.73
/proc/1535/stat : 1535 (unclasp) R 1523 1523 1511 34817 1511 4202496 91742 0 10 0 1024 49 0 0 25 0 1 0 558066 34074624 7380 1283457024 134512640 135121179 4290414896 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/1535/statm: 8319 7380 333 149 0 7510 0
Current children cumulated CPU time (s) 13.84
Current children cumulated vsize (KiB) 35872

[startup+14.8101 s]
/proc/loadavg: 0.29 0.06 0.02 2/38 1537
/proc/meminfo: memFree=832212/1048576 swapFree=0/0
[pid=1523] ppid=1522 vsize=2596 CPUtime=3.11
/proc/1523/stat : 1523 (aspuncud-trendy) S 1522 1523 1511 34817 1511 4202496 624 23861 0 39 0 0 302 9 15 0 1 0 558063 2658304 298 1283457024 134512640 135304128 4291946304 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1523/statm: 649 298 251 194 0 36 0
[pid=1535] ppid=1523 vsize=33928 CPUtime=11.13
/proc/1535/stat : 1535 (unclasp) R 1523 1523 1511 34817 1511 4202496 95249 0 10 0 1061 52 0 0 25 0 1 0 558066 34742272 7543 1283457024 134512640 135121179 4290414896 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/1535/statm: 8482 7543 333 149 0 7673 0
Current children cumulated CPU time (s) 14.24
Current children cumulated vsize (KiB) 36524

Child status: 0
Real time (s): 14.8862
CPU time (s): 14.3249
CPU user time (s): 13.6849
CPU system time (s): 0.64004
CPU usage (%): 96.2294
Max. virtual memory (cumulated for all children) (KiB): 73276

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.6849
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= 122547
page faults= 49
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1621
involuntary context switches= 1380

runsolver used 0 second user time and 0 second system time

The end