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/201103031013/uns-trendy-0.0004/1dcce248-4bb4-11df-9e6e-00163e7a6f5e.cudf.debian.log.runsolver ./uns-trendy-0.0004 /home/misc2010/data/misc4/debian//1dcce248-4bb4-11df-9e6e-00163e7a6f5e.cudf /home/misc2010/tmp/201103031013/uns-trendy-0.0004/1dcce248-4bb4-11df-9e6e-00163e7a6f5e.cudf.debian.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.08 1.04 0.64 2/36 4175
/proc/meminfo: memFree=686916/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=3024 CPUtime=0
/proc/4175/stat : 4175 (runsolver) D 4174 4175 29493 34817 29493 4202560 73 0 0 0 0 0 0 0 25 0 1 0 74709871 3096576 94 1283457024 134512640 134586868 4291519952 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/4175/statm: 756 94 62 19 0 55 0

[startup+0.377022 s]
/proc/loadavg: 1.08 1.04 0.64 2/36 4175
/proc/meminfo: memFree=686916/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1668

[startup+0.407044 s]
/proc/loadavg: 1.08 1.04 0.64 2/36 4175
/proc/meminfo: memFree=686916/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1668

[startup+0.507057 s]
/proc/loadavg: 1.08 1.04 0.64 2/36 4175
/proc/meminfo: memFree=686916/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1668

[startup+0.707097 s]
/proc/loadavg: 1.08 1.04 0.64 2/36 4175
/proc/meminfo: memFree=686916/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1668

[startup+1.50728 s]
/proc/loadavg: 1.08 1.04 0.64 2/38 4177
/proc/meminfo: memFree=638424/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
[pid=4177] ppid=4175 vsize=61660 CPUtime=1.36
/proc/4177/stat : 4177 (cudfsolver-stat) R 4175 4175 29493 34817 29493 4202496 14008 0 18 0 133 3 0 0 25 0 1 0 74709872 63139840 13692 1283457024 134512640 141746657 4293286016 18446744073709551615 134600760 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4177/statm: 15415 13692 150 1767 0 13625 0
Current children cumulated CPU time (s) 1.36
Current children cumulated vsize (KiB) 63328

[startup+3.10774 s]
/proc/loadavg: 1.08 1.04 0.64 2/38 4177
/proc/meminfo: memFree=595024/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
[pid=4177] ppid=4175 vsize=154252 CPUtime=2.96
/proc/4177/stat : 4177 (cudfsolver-stat) R 4175 4175 29493 34817 29493 4202496 33446 0 18 0 288 8 0 0 25 0 1 0 74709872 157954048 31892 1283457024 134512640 141746657 4293286016 18446744073709551615 138838807 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4177/statm: 38563 31892 425 1767 0 36410 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 155920

[startup+6.30865 s]
/proc/loadavg: 1.08 1.04 0.64 2/38 4177
/proc/meminfo: memFree=553608/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
[pid=4177] ppid=4175 vsize=154252 CPUtime=6.16
/proc/4177/stat : 4177 (cudfsolver-stat) R 4175 4175 29493 34817 29493 4202496 35362 0 18 0 608 8 0 0 25 0 1 0 74709872 157954048 33808 1283457024 134512640 141746657 4293286016 18446744073709551615 138880726 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4177/statm: 38563 33808 468 1767 0 36410 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 155920

[startup+12.7105 s]
/proc/loadavg: 1.07 1.04 0.64 2/38 4177
/proc/meminfo: memFree=559932/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
[pid=4177] ppid=4175 vsize=160588 CPUtime=12.55
/proc/4177/stat : 4177 (cudfsolver-stat) R 4175 4175 29493 34817 29493 4202496 38551 0 18 0 1245 10 0 0 25 0 1 0 74709872 164442112 34485 1283457024 134512640 141746657 4293286016 18446744073709551615 135793914 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4177/statm: 40147 34485 521 1767 0 37994 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 162256

[startup+25.5045 s]
/proc/loadavg: 1.05 1.03 0.65 2/38 4177
/proc/meminfo: memFree=512936/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
[pid=4177] ppid=4175 vsize=200720 CPUtime=25.34
/proc/4177/stat : 4177 (cudfsolver-stat) R 4175 4175 29493 34817 29493 4202496 51476 0 18 0 2514 20 0 0 25 0 1 0 74709872 205537280 43713 1283457024 134512640 141746657 4293286016 18446744073709551615 136221504 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4177/statm: 50180 43713 679 1767 0 48027 0
Current children cumulated CPU time (s) 25.34
Current children cumulated vsize (KiB) 202388

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

[startup+25.8046 s]
/proc/loadavg: 1.05 1.03 0.65 2/38 4177
/proc/meminfo: memFree=512936/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
[pid=4177] ppid=4175 vsize=200720 CPUtime=25.64
/proc/4177/stat : 4177 (cudfsolver-stat) R 4175 4175 29493 34817 29493 4202496 53632 0 18 0 2544 20 0 0 25 0 1 0 74709872 205537280 45869 1283457024 134512640 141746657 4293286016 18446744073709551615 138887834 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4177/statm: 50180 45869 679 1767 0 48027 0
Current children cumulated CPU time (s) 25.64
Current children cumulated vsize (KiB) 202388

[startup+32.2111 s]
/proc/loadavg: 1.05 1.03 0.65 2/38 4177
/proc/meminfo: memFree=434420/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
[pid=4177] ppid=4175 vsize=267276 CPUtime=31.88
/proc/4177/stat : 4177 (cudfsolver-stat) R 4175 4175 29493 34817 29493 4202496 106374 0 36 0 3139 49 0 0 25 0 1 0 74709872 273690624 63167 1283457024 134512640 141746657 4293286016 18446744073709551615 134740100 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4177/statm: 66819 63167 836 1767 0 64666 0
Current children cumulated CPU time (s) 31.88
Current children cumulated vsize (KiB) 268944

[startup+35.412 s]
/proc/loadavg: 1.04 1.03 0.65 2/38 4177
/proc/meminfo: memFree=446200/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
[pid=4177] ppid=4175 vsize=251184 CPUtime=35.08
/proc/4177/stat : 4177 (cudfsolver-stat) R 4175 4175 29493 34817 29493 4202496 112191 0 36 0 3457 51 0 0 25 0 1 0 74709872 257212416 60089 1283457024 134512640 141746657 4293286016 18446744073709551615 136235579 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4177/statm: 62796 60089 841 1767 0 60643 0
Current children cumulated CPU time (s) 35.08
Current children cumulated vsize (KiB) 252852

[startup+37.0024 s]
/proc/loadavg: 1.04 1.03 0.65 2/38 4177
/proc/meminfo: memFree=446200/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
[pid=4177] ppid=4175 vsize=251184 CPUtime=36.67
/proc/4177/stat : 4177 (cudfsolver-stat) R 4175 4175 29493 34817 29493 4202496 112191 0 36 0 3616 51 0 0 25 0 1 0 74709872 257212416 60089 1283457024 134512640 141746657 4293286016 18446744073709551615 136223314 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4177/statm: 62796 60089 841 1767 0 60643 0
Current children cumulated CPU time (s) 36.67
Current children cumulated vsize (KiB) 252852

[startup+38.6127 s]
/proc/loadavg: 1.04 1.03 0.65 2/38 4177
/proc/meminfo: memFree=446200/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
[pid=4177] ppid=4175 vsize=251184 CPUtime=38.28
/proc/4177/stat : 4177 (cudfsolver-stat) R 4175 4175 29493 34817 29493 4202496 112192 0 36 0 3777 51 0 0 25 0 1 0 74709872 257212416 60089 1283457024 134512640 141746657 4293286016 18446744073709551615 135021551 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4177/statm: 62796 60089 841 1767 0 60643 0
Current children cumulated CPU time (s) 38.28
Current children cumulated vsize (KiB) 252852

[startup+39.4129 s]
/proc/loadavg: 1.04 1.03 0.65 2/38 4177
/proc/meminfo: memFree=446200/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
[pid=4177] ppid=4175 vsize=251184 CPUtime=39.08
/proc/4177/stat : 4177 (cudfsolver-stat) R 4175 4175 29493 34817 29493 4202496 112192 0 36 0 3857 51 0 0 25 0 1 0 74709872 257212416 60089 1283457024 134512640 141746657 4293286016 18446744073709551615 138905586 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4177/statm: 62796 60089 841 1767 0 60643 0
Current children cumulated CPU time (s) 39.08
Current children cumulated vsize (KiB) 252852

[startup+39.8129 s]
/proc/loadavg: 1.04 1.03 0.65 2/38 4177
/proc/meminfo: memFree=446200/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
[pid=4177] ppid=4175 vsize=251184 CPUtime=39.48
/proc/4177/stat : 4177 (cudfsolver-stat) R 4175 4175 29493 34817 29493 4202496 112197 0 36 0 3897 51 0 0 25 0 1 0 74709872 257212416 60094 1283457024 134512640 141746657 4293286016 18446744073709551615 136876588 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4177/statm: 62796 60094 846 1767 0 60643 0
Current children cumulated CPU time (s) 39.48
Current children cumulated vsize (KiB) 252852

[startup+39.9129 s]
/proc/loadavg: 1.04 1.03 0.65 2/38 4177
/proc/meminfo: memFree=446200/1048576 swapFree=0/0
[pid=4175] ppid=4174 vsize=1668 CPUtime=0
/proc/4175/stat : 4175 (uns-trendy-0.00) S 4174 4175 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 25 0 1 0 74709871 1708032 129 1283457024 134512640 134593992 4293537952 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/4175/statm: 417 129 113 20 0 44 0
[pid=4177] ppid=4175 vsize=248524 CPUtime=39.58
/proc/4177/stat : 4177 (cudfsolver-stat) R 4175 4175 29493 34817 29493 4202496 112269 0 36 0 3907 51 0 0 25 0 1 0 74709872 254488576 59430 1283457024 134512640 141746657 4293286016 18446744073709551615 134644439 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4177/statm: 62131 59430 847 1767 0 59978 0
Current children cumulated CPU time (s) 39.58
Current children cumulated vsize (KiB) 250192

Child status: 0
Real time (s): 39.9655
CPU time (s): 39.6425
CPU user time (s): 39.0944
CPU system time (s): 0.548034
CPU usage (%): 99.1917
Max. virtual memory (cumulated for all children) (KiB): 298680

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 39.0944
system time used= 0.548034
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 112489
page faults= 36
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 41
involuntary context switches= 485

runsolver used 0 second user time and 0 second system time

The end