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/4040.cudf.caixa.log.runsolver ./uns-trendy-0.0004 /home/misc2010/data/misc4/caixa//4040.cudf /home/misc2010/tmp/201103031013/uns-trendy-0.0004/4040.cudf.caixa.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.66 1.69 1.69 4/36 31789
/proc/meminfo: memFree=306380/1048576 swapFree=0/0
[pid=31788] ppid=31787 vsize=1676 CPUtime=0
/proc/31788/stat : 31788 (uns-trendy-0.00) S 31787 31788 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 18 0 1 0 76128606 1716224 130 1283457024 134512640 134593992 4293019744 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31788/statm: 419 130 113 20 0 46 0
[pid=31789] ppid=31788 vsize=7704 CPUtime=0.01
/proc/31789/stat : 31789 (cudfsolver-stat) R 31788 31788 29493 34817 29493 4202496 275 0 0 0 1 0 0 0 25 0 1 0 76128606 7888896 231 1283457024 134512640 141746657 4287279760 18446744073709551615 140925765 0 0 0 0 0 0 0 17 0 0 0 0
/proc/31789/statm: 1926 231 147 1767 0 136 0

[startup+0.144588 s]
/proc/loadavg: 1.66 1.69 1.69 4/36 31789
/proc/meminfo: memFree=306380/1048576 swapFree=0/0
[pid=31788] ppid=31787 vsize=1676 CPUtime=0
/proc/31788/stat : 31788 (uns-trendy-0.00) S 31787 31788 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 18 0 1 0 76128606 1716224 130 1283457024 134512640 134593992 4293019744 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31788/statm: 419 130 113 20 0 46 0
[pid=31789] ppid=31788 vsize=17248 CPUtime=0.15
/proc/31789/stat : 31789 (cudfsolver-stat) R 31788 31788 29493 34817 29493 4202496 2733 0 0 0 13 2 0 0 25 0 1 0 76128606 17661952 2630 1283457024 134512640 141746657 4287279760 18446744073709551615 140925807 0 0 0 0 0 0 0 17 0 0 0 0
/proc/31789/statm: 4312 2630 148 1767 0 2522 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 18924

[startup+0.2046 s]
/proc/loadavg: 1.66 1.69 1.69 4/36 31789
/proc/meminfo: memFree=306380/1048576 swapFree=0/0
[pid=31788] ppid=31787 vsize=1676 CPUtime=0
/proc/31788/stat : 31788 (uns-trendy-0.00) S 31787 31788 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 18 0 1 0 76128606 1716224 130 1283457024 134512640 134593992 4293019744 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31788/statm: 419 130 113 20 0 46 0
[pid=31789] ppid=31788 vsize=20696 CPUtime=0.21
/proc/31789/stat : 31789 (cudfsolver-stat) R 31788 31788 29493 34817 29493 4202496 3604 0 0 0 18 3 0 0 25 0 1 0 76128606 21192704 3473 1283457024 134512640 141746657 4287279760 18446744073709551615 134632224 0 0 0 0 0 0 0 17 0 0 0 0
/proc/31789/statm: 5174 3473 148 1767 0 3384 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 22372

[startup+0.304633 s]
/proc/loadavg: 1.66 1.69 1.69 4/36 31789
/proc/meminfo: memFree=306380/1048576 swapFree=0/0
[pid=31788] ppid=31787 vsize=1676 CPUtime=0
/proc/31788/stat : 31788 (uns-trendy-0.00) S 31787 31788 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 18 0 1 0 76128606 1716224 130 1283457024 134512640 134593992 4293019744 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31788/statm: 419 130 113 20 0 46 0
[pid=31789] ppid=31788 vsize=26876 CPUtime=0.3
/proc/31789/stat : 31789 (cudfsolver-stat) R 31788 31788 29493 34817 29493 4202496 5206 0 0 0 26 4 0 0 25 0 1 0 76128606 27521024 4997 1283457024 134512640 141746657 4287279760 18446744073709551615 134632212 0 0 0 0 0 0 0 17 0 0 0 0
/proc/31789/statm: 6719 4997 148 1767 0 4929 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 28552

[startup+0.704747 s]
/proc/loadavg: 1.66 1.69 1.69 4/36 31789
/proc/meminfo: memFree=306380/1048576 swapFree=0/0
[pid=31788] ppid=31787 vsize=1676 CPUtime=0
/proc/31788/stat : 31788 (uns-trendy-0.00) S 31787 31788 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 18 0 1 0 76128606 1716224 130 1283457024 134512640 134593992 4293019744 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31788/statm: 419 130 113 20 0 46 0
[pid=31789] ppid=31788 vsize=49848 CPUtime=0.71
/proc/31789/stat : 31789 (cudfsolver-stat) R 31788 31788 29493 34817 29493 4202496 11204 0 0 0 64 7 0 0 25 0 1 0 76128606 51044352 10702 1283457024 134512640 141746657 4287279760 18446744073709551615 134632319 0 0 0 0 0 0 0 17 0 0 0 0
/proc/31789/statm: 12462 10702 148 1767 0 10672 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 51524

[startup+1.50501 s]
/proc/loadavg: 1.66 1.69 1.69 2/37 31790
/proc/meminfo: memFree=245476/1048576 swapFree=0/0
[pid=31788] ppid=31787 vsize=1676 CPUtime=0
/proc/31788/stat : 31788 (uns-trendy-0.00) S 31787 31788 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 18 0 1 0 76128606 1716224 130 1283457024 134512640 134593992 4293019744 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31788/statm: 419 130 113 20 0 46 0
[pid=31789] ppid=31788 vsize=79256 CPUtime=1.49
/proc/31789/stat : 31789 (cudfsolver-stat) R 31788 31788 29493 34817 29493 4202496 17213 0 0 0 140 9 0 0 25 0 1 0 76128606 81158144 16577 1283457024 134512640 141746657 4287279760 18446744073709551615 138106289 0 0 0 0 0 0 0 17 0 0 0 0
/proc/31789/statm: 19814 16577 480 1767 0 17661 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 80932

[startup+3.10536 s]
/proc/loadavg: 1.61 1.68 1.69 2/37 31791
/proc/meminfo: memFree=240640/1048576 swapFree=0/0
[pid=31788] ppid=31787 vsize=1676 CPUtime=0
/proc/31788/stat : 31788 (uns-trendy-0.00) S 31787 31788 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 18 0 1 0 76128606 1716224 130 1283457024 134512640 134593992 4293019744 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31788/statm: 419 130 113 20 0 46 0
[pid=31789] ppid=31788 vsize=93692 CPUtime=3.1
/proc/31789/stat : 31789 (cudfsolver-stat) R 31788 31788 29493 34817 29493 4202496 20620 0 0 0 296 14 0 0 25 0 1 0 76128606 95940608 19130 1283457024 134512640 141746657 4287279760 18446744073709551615 138428234 0 0 0 0 0 0 0 17 0 0 0 0
/proc/31789/statm: 23423 19130 768 1767 0 21270 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 95368

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

[startup+3.20535 s]
/proc/loadavg: 1.61 1.68 1.69 2/37 31791
/proc/meminfo: memFree=240640/1048576 swapFree=0/0
[pid=31788] ppid=31787 vsize=1676 CPUtime=0
/proc/31788/stat : 31788 (uns-trendy-0.00) S 31787 31788 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 18 0 1 0 76128606 1716224 130 1283457024 134512640 134593992 4293019744 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31788/statm: 419 130 113 20 0 46 0
[pid=31789] ppid=31788 vsize=93692 CPUtime=3.2
/proc/31789/stat : 31789 (cudfsolver-stat) R 31788 31788 29493 34817 29493 4202496 20895 0 0 0 306 14 0 0 25 0 1 0 76128606 95940608 19405 1283457024 134512640 141746657 4287279760 18446744073709551615 134740120 0 0 0 0 0 0 0 17 0 0 0 0
/proc/31789/statm: 23423 19405 793 1767 0 21270 0
Current children cumulated CPU time (s) 3.2
Current children cumulated vsize (KiB) 95368

[startup+3.60547 s]
/proc/loadavg: 1.61 1.68 1.69 2/37 31791
/proc/meminfo: memFree=232084/1048576 swapFree=0/0
[pid=31788] ppid=31787 vsize=1676 CPUtime=0
/proc/31788/stat : 31788 (uns-trendy-0.00) S 31787 31788 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 18 0 1 0 76128606 1716224 130 1283457024 134512640 134593992 4293019744 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31788/statm: 419 130 113 20 0 46 0
[pid=31789] ppid=31788 vsize=93692 CPUtime=3.6
/proc/31789/stat : 31789 (cudfsolver-stat) R 31788 31788 29493 34817 29493 4202496 20895 0 0 0 346 14 0 0 25 0 1 0 76128606 95940608 19405 1283457024 134512640 141746657 4287279760 18446744073709551615 134739922 0 0 0 0 0 0 0 17 0 0 0 0
/proc/31789/statm: 23423 19405 793 1767 0 21270 0
Current children cumulated CPU time (s) 3.6
Current children cumulated vsize (KiB) 95368

[startup+4.00561 s]
/proc/loadavg: 1.61 1.68 1.69 2/37 31791
/proc/meminfo: memFree=232084/1048576 swapFree=0/0
[pid=31788] ppid=31787 vsize=1676 CPUtime=0
/proc/31788/stat : 31788 (uns-trendy-0.00) S 31787 31788 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 18 0 1 0 76128606 1716224 130 1283457024 134512640 134593992 4293019744 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31788/statm: 419 130 113 20 0 46 0
[pid=31789] ppid=31788 vsize=110076 CPUtime=3.98
/proc/31789/stat : 31789 (cudfsolver-stat) R 31788 31788 29493 34817 29493 4202496 23581 0 0 0 384 14 0 0 25 0 1 0 76128606 112717824 21505 1283457024 134512640 141746657 4287279760 18446744073709551615 134946785 0 0 0 0 0 0 0 17 0 0 0 0
/proc/31789/statm: 27519 21505 788 1767 0 25366 0
Current children cumulated CPU time (s) 3.98
Current children cumulated vsize (KiB) 111752

[startup+4.10567 s]
/proc/loadavg: 1.61 1.68 1.69 2/37 31791
/proc/meminfo: memFree=232084/1048576 swapFree=0/0
[pid=31788] ppid=31787 vsize=1676 CPUtime=0
/proc/31788/stat : 31788 (uns-trendy-0.00) S 31787 31788 29493 34817 29493 4202496 215 0 0 0 0 0 0 0 18 0 1 0 76128606 1716224 130 1283457024 134512640 134593992 4293019744 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/31788/statm: 419 130 113 20 0 46 0
[pid=31789] ppid=31788 vsize=93696 CPUtime=4.09
/proc/31789/stat : 31789 (cudfsolver-stat) R 31788 31788 29493 34817 29493 4202496 23704 0 0 0 393 16 0 0 25 0 1 0 76128606 95944704 18454 1283457024 134512640 141746657 4287279760 18446744073709551615 140885647 0 0 0 0 0 0 0 17 0 0 0 0
/proc/31789/statm: 23424 18454 789 1767 0 21271 0
Current children cumulated CPU time (s) 4.09
Current children cumulated vsize (KiB) 95372

Child status: 0
Real time (s): 4.15925
CPU time (s): 4.14426
CPU user time (s): 3.96825
CPU system time (s): 0.176011
CPU usage (%): 99.6397
Max. virtual memory (cumulated for all children) (KiB): 111752

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.96825
system time used= 0.176011
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 23924
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= 3
involuntary context switches= 62

runsolver used 0 second user time and 0 second system time

The end