Motor getting slower

This is where you talk about the NXJ hardware related topics such as the brick, sensors, LEGO pieces, etc.

Moderators: 99jonathan, roger, imaqine

Motor getting slower

Postby aklarl » Fri Aug 27, 2010 1:44 pm

Hello at all,

my NXT is doing some weird stuff. It is driving along a line with some speed and suddenly the motor slows down. I've tracked down when this happens. Besides the line following behavior another thread logs log messages to a file. If the flash memory is full, the logging-thread will stop writing to the file, close the file and wait until another thread notifies this logging-thread. (That means this thread does not terminate!). If this happens (the flash-memory is full and the logging-thread switches to waiting), the motor will slow down. Does anybody know why this happens? Should I suspend the logging-thread with any other method than wait?

By the way, I am using the developer snapshot as there are some very useful bugfixes :-)

Thank you! Greets...
aklarl
New User
 
Posts: 21
Joined: Sun May 30, 2010 10:56 am

Re: Motor getting slower

Postby skoehler » Fri Aug 27, 2010 2:12 pm

Is suspect that, if it would be a threading issue, the regulation thread would simple be slower than usually, causing the motor to be more inaccurate, but not slower or faster instead.

My only explanation would be, that the regulation thread crashes for some reason, and the Motor is left in an unregulated state. Not sure thought.
skoehler
leJOS Team Member
 
Posts: 1390
Joined: Thu Oct 30, 2008 4:54 pm

Postby gloomyandy » Fri Aug 27, 2010 2:56 pm

Do you see the problem if you don't have your logging thread running? In general you need to be a little careful when writing to flash as when you do this everything on the NXT has to stop for a few ms... How are you working out if the flash system is full? If you can create a simple test program (one that does not require me to build a robot!), I'll try and take a look at what is going on...

Andy
User avatar
gloomyandy
leJOS Team Member
 
Posts: 3901
Joined: Fri Sep 28, 2007 2:06 pm
Location: UK

Postby aklarl » Fri Aug 27, 2010 7:44 pm

Thanks at both of you!

It is definitely the case that the motor does some weird stuff if the logging thread waits after closing the file. While the logging thread is running (and writing to the file on the flash), the motor moves pretty constantly. I can't see any stops at all while the logger is writing (Is it really the case that the pilot stops for a few moments while writing to the flash?)

Underneath you will find a little test program. It only needs a motor plugged in at port A. I start a writer thread that opens a file named test.txt. The logging thread writes as fast as possible the current time millis to the file. It stopps when the flash memory has only 145 000 bytes left (testet with File.freeMemory() ). While the thread is writing to the file, the motor (that is started in the main thread) moves constantly forward, but when the logging thread closes the log file and waits, the motor stops immediately. I am a little confused :-(.


Code: Select all
public class FlashMotorTest {
   public static void main(String[] args) {
      LogRunnable logRunnable = new LogRunnable();
      Thread logThread = new Thread(logRunnable, "LogThread");
      logThread.start();

      Motor.A.forward();

      Button.waitForPress();
      synchronized (logRunnable) {
         logRunnable.notify();
      }
   }
}
Code: Select all
public class LogRunnable implements Runnable {

   private static FileOutputStream initFileOutput(String fileName) {
      File file = new File(fileName);
      if (file.exists()) {
         file.delete();
      }
      try {
         file.createNewFile();
      }
      catch (IOException e) {
         System.out.println("No logger!");
      }

      // for freeing the resources if a big file was deleted
      File.freeMemory();

      return new FileOutputStream(file);
   }

   @Override
   public void run() {
      FileOutputStream output = initFileOutput("test.txt");
      try {
         byte currentMessage;
         while (true) {
            try {
               currentMessage = new Long(System.currentTimeMillis())
                     .byteValue();
               System.out.println(currentMessage);
               if (File.freeMemory() > 145000) {
                  output.write(currentMessage);
                  output.flush();
               }
               else {
                  throw new Exception("NO SPACE");
               }
            }
            catch (IOException e) {
            }
         }
      }

      catch (Throwable e) {
         System.out.println(e.getMessage());
      }

      finally {
         try {
            output.close();
         }
         catch (IOException e) {
         }

         System.out.println("closed");
         synchronized (this) {
            try {
               this.wait();
            }
            catch (InterruptedException e) {
               e.printStackTrace();
            }
         }
      }
   }

}


Apropos, Andy asked how I check that the flash memory is full: I sometimes have the problem that even if I delete a previous created log file programmatically, the logger thread cannot write to the flash because File.freeMemory() returns less than there must actually be after deleting the old log file. Is there some problem with the file handling?
aklarl
New User
 
Posts: 21
Joined: Sun May 30, 2010 10:56 am

Postby gloomyandy » Fri Aug 27, 2010 9:02 pm

The leJOS file system is very simple and only uses contiguous files. This means that it may need to move a file around to keep the space contiguous. However, your program is running from flash memory and it is not possible to move it while it is running (well not easily anyway), this means that free space may not be available when you delete an existing file (the menu code will compact the file system when it next runs and the free space will appear then)...

As to your problem I can't run your code just now. But I will when I get chance. Have you tried not writing to the file? What about if you don't close it?

Yes when you write to flash we have to stop pretty much everything running on the ARM chip (the motor PWM drive will continue because it is on another processor), this include the motor regulator (which is written in Java). But this should only be for a few ms at a time. On possible problem is that your code will be writing very fast to flash, which may be causing parts of the system to get into trouble, because they are not getting chance to run. What happens if you insert a sleep(1) into your writing loop?

Finally is there a reason for you leaving 145,000 bytes free? I would have thought that this will happen very quickly. How many bytes are free when you start to run your program?

Andy
User avatar
gloomyandy
leJOS Team Member
 
Posts: 3901
Joined: Fri Sep 28, 2007 2:06 pm
Location: UK

Postby aklarl » Fri Aug 27, 2010 9:54 pm

Hey Andy,
thank you for your explanation of the file system. Now it's clear, why the free space might not be available after the deletion.

The test program:
Yes, there is a reason why I am leaving 145 000 bytes. It's just for this test program ;-). So that I don't have to wait too long to fill the test file and to meet the termination condition. Normally, I am writing to the file until the flash is full.

I have inserted a wait(1) in my writer thread after writing one byte. I don't see any changes in the behavior of the motor. But perhaps it might not be visible for an human eye?!

I also tried not to close the output file. So I first wait for a notify and after the notify, the file will be closed. With this program, the motor continued to drive in normal speed for some while after the writing was stopped, but after one second or so it also stopped. (By the way, when I am starting the test program the second time, without deleting the test.txt in the menu beforehands, sometimes the motor will drive slower from the beginning. The writer thread will not log anything. It's the same whether I close the file before waiting or afterwards.)

When I am not writing to a file (so I simply commented the lines with output.write and output.flush), the motor will drive slower from the beginning.

It's really interesting. I am very excited which results you will get...
aklarl
New User
 
Posts: 21
Joined: Sun May 30, 2010 10:56 am

Postby gloomyandy » Sat Aug 28, 2010 9:22 am

Hi,
OK I've tried your program and I understand what is happening. Here is a slightly modified version of your program to help you understand what is going on...
Code: Select all

import lejos.nxt.*;
import java.io.*;
import lejos.util.Delay;

class LogRunnable implements Runnable {

   private static FileOutputStream initFileOutput(String fileName) {
      File file = new File(fileName);
      if (file.exists()) {
         file.delete();
      }
      try {
         file.createNewFile();
      }
      catch (IOException e) {
         System.out.println("No logger!");
      }

      // for freeing the resources if a big file was deleted
      File.freeMemory();

      return new FileOutputStream(file);
   }

   @Override
   public void run() {
      FileOutputStream output = initFileOutput("test.txt");
      long maxTime = 0;
      try {
         byte currentMessage;
         while (true) {
            try {
               currentMessage = new Long(System.currentTimeMillis())
                     .byteValue();
               System.out.println(currentMessage);
               if (File.freeMemory() > 145000) {
                  long s = System.currentTimeMillis();
                  output.write(currentMessage);
                  long t = System.currentTimeMillis() - s;
                  if (t > maxTime) maxTime = t;
                  //output.flush();
                  //Delay.msDelay(10);
               }
               else {
                  throw new Exception("NO SPACE");
               }
            }
            catch (IOException e) {
            }
         }
      }

      catch (Throwable e) {
         System.out.println(e.getMessage());
      }

      finally {
         try {
            output.close();
         }
         catch (IOException e) {
         }

         System.out.println("closed");
         System.out.println("Time: " + maxTime);
         synchronized (this) {
            try {
               this.wait();
            }
            catch (InterruptedException e) {
               e.printStackTrace();
            }
         }
      }
   }

}

public class FileTest {
   public static void main(String[] args) {
      LogRunnable logRunnable = new LogRunnable();
      Thread logThread = new Thread(logRunnable, "LogThread");

      Motor.A.forward();
      Delay.msDelay(10000);
      logThread.start();
      Button.waitForPress();
      synchronized (logRunnable) {
         logRunnable.notify();
      }
   }



You will see that I've made a few changes.
1. I allow the motor to run for 10 seconds before starting the logging thread. This is to show what the correctly regulated speed is.
2. I've added code to record the maximum time taken by a write to the file.
3. I've commented out the flush statement.

Ok so when this version is run what happens is that the motor will run for a while relatively slowly. This is the correct regulated default speed (you can use the setSpeed call to make it faster if that is what you want). Then when the logger starts you will probably notice that the speed of the motor jumps a little from time to time, you will also notice that the file is written much faster than with your version. Finally you will see at the end that the motor returns to the original speed and the time for the longest write is displayed, on my NXT this is 9ms.

So what is going on here. Well as you can see it can take up to 9ms to write a file system page to flash memory and during that time nothing else can run on the NXT. This means that during that time the speed of the motor is unregulated. In my test program I let the system decide when to flush the file data to flash (by removing the flush call) and so the 9ms delay only happens every 256 writes (each flash page is 256 bytes in size). When the write takes place the motor speed will "glitch" a little. In your program you flushed the data after every write. This means that the file was being written to flash every time and each write was taking approx 9ms. This will mean in effect that the motor is unregulated pretty much all of the time, which means that it will run at some uncontrolled speed, which seems to be full speed. Then when the file is full, the regulator will get chance to run and will once again reduce the speed...

So what can you do if you want to use logging to a file. Well obviously don't call flush all of the time. If you don't do this then you will find that the logging thread will run much faster so you may want to add a delay after each write. In my test program I added a 10ms delay to give about the same data rate as your original program. With this the speed of the motor was pretty constant with just a slight glitch every time the file was written. An alternative (which I use a lot), would be to use a Bluetooth (or USB) connection and log to that, this way you avoid the issues with the file system and you can see the data in real time on your PC.

Hope the above makes some sort of sense. If not please ask for more details....

Andy
User avatar
gloomyandy
leJOS Team Member
 
Posts: 3901
Joined: Fri Sep 28, 2007 2:06 pm
Location: UK

Postby aklarl » Mon Aug 30, 2010 9:10 am

Thank you, Andy! I can see the problem now. For my application, I just removed the flush-statement and it is running so much better now.

About the topic of logging to a file or via bluetooth to a pc: I decided to log to a file because I was thinking that logging via bluetooth might be pretty slow. I have multiple bluetooth connections per nxt for my application and I thought one connection more for the logging might slow down the whole application further on. How is your experience with this? Does the logging to a pc influence your applications?

But once more thank you for the advice!
aklarl
New User
 
Posts: 21
Joined: Sun May 30, 2010 10:56 am

Postby gloomyandy » Mon Aug 30, 2010 9:27 am

Hi,
I guess it all depends on the volume of logging data. Certainly adding another connection will slow things down. But as you have seen using flash has its own issues! If you already have a connection to a PC you perhaps add the logging into that existing connection. I tend to find that with robots having an easy to way to establish what is going on is so important that I make some form of logging part of the actual design rather than adding it on later. So having a log/status packet as part of the normal BT connection often works for me.

This is one of the things that makes these sorts of projects so interesting to me. You are always working with a very constrained set of resources (much more so than on desktop/server systems), and finding the optimal way to use the various hardware and software systems that you have available is often key. In your case you have already used a lot of the BT resources that are available and so using the flash resource may be the best way to go... All adds to the fun!

Thanks for raising this issue, the flash file system is probably a little neglected in leJOS, we tend to think of it more as a place to keep programs, perhaps we need to do a little more work in this area!

All the best

Andy
User avatar
gloomyandy
leJOS Team Member
 
Posts: 3901
Joined: Fri Sep 28, 2007 2:06 pm
Location: UK


Return to NXJ Hardware

Who is online

Users browsing this forum: No registered users and 1 guest

more stuff