Show
added a comment - - edited Observation:
The histmem scan for att=60 is takes only half of the usual time (12sec).
Coming out from GumTree log:
2010-06-20 00:12:21,643 INFO [pool-5-thread-1] org.gumtree.gumnix.sics.internal
.io.SicsChannel:scan - Client sent: contextdo 480 hset /commands/histogram/histm
em start
2010-06-20 00:12:21,831 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 1, "object" :
"hnotify" , "flag" : "hdbevent" , "data" : { "/commands/histogram/histmem/feedback/
status ": " STARTING" } }
2010-06-20 00:12:25,222 INFO [ Thread -11] org.gumtree.gumnix.sics.internal.io.Si
csSocketListener:general - Server replied: { "con" : 171858, "trans" : 480, "objec
t ": " hset ", " flag ": " out ", " data ": " histmem stopped" }
2010-06-20 00:12:25,222 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 2, "object" :
"statemon" , "flag" : "warning" , "data" : "FINISH = histmem" }
2010-06-20 00:12:25,222 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 3, "object" :
"statemon" , "flag" : "warning" , "data" : "/commands/histogram/histmem FINISH" }
2010-06-20 00:12:27,847 INFO [ Thread -11] org.gumtree.gumnix.sics.internal.io.Si
csSocketListener:general - Server replied: { "con" : 171858, "trans" : 480, "objec
t ": " hset ", " flag ": " out ", " data ": " histmem stopped" }
2010-06-20 00:12:27,847 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 2, "object" :
"statemon" , "flag" : "warning" , "data" : "FINISH = histmem" }
2010-06-20 00:12:27,847 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 3, "object" :
"statemon" , "flag" : "warning" , "data" : "/commands/histogram/histmem FINISH" }
2010-06-20 00:12:30,581 INFO [ Thread -11] org.gumtree.gumnix.sics.internal.io.Si
csSocketListener:general - Server replied: { "con" : 171858, "trans" : 480, "objec
t ": " hset ", " flag ": " out ", " data ": " histmem stopped" }
2010-06-20 00:12:30,581 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 2, "object" :
"statemon" , "flag" : "warning" , "data" : "FINISH = histmem" }
2010-06-20 00:12:30,581 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 3, "object" :
"statemon" , "flag" : "warning" , "data" : "/commands/histogram/histmem FINISH" }
2010-06-20 00:12:33,315 INFO [ Thread -11] org.gumtree.gumnix.sics.internal.io.Si
csSocketListener:general - Server replied: { "con" : 171858, "trans" : 480, "objec
t ": " hset ", " flag ": " out ", " data ": " histmem started" }
2010-06-20 00:12:33,315 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 2, "object" :
"statemon" , "flag" : "warning" , "data" : "STARTED = histmem" }
2010-06-20 00:12:33,331 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 2, "object" :
"statemon" , "flag" : "warning" , "data" : "STARTED = hmcontrol" }
2010-06-20 00:12:33,331 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 1, "object" :
"hnotify" , "flag" : "hdbevent" , "data" : { "/commands/histogram/histmem/feedback/
status ": " BUSY" } }
2010-06-20 00:12:33,347 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 4, "object" :
"status" , "flag" : "warning" , "data" : "status = Counting" }
2010-06-20 00:12:34,347 INFO [pool-5-thread-1] org.gumtree.gumnix.sics.internal
.io.SicsChannel:general - Client sent: contextdo 3910 hset /instrument/collimato
r/att 30.0
2010-06-20 00:12:34,519 INFO [ Thread -8] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171854, "trans" : 3910, "objec
t ": " hset ", " flag ": " error ", " data ": " ERROR: somebody else is still driving, Req
uest rejected" }
2010-06-20 00:12:42,722 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 1, "object" :
"hnotify" , "flag" : "hdbevent" , "data" : { "/commands/histogram/histmem/feedback/
status ": " IDLE" } }
2010-06-20 00:12:43,378 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 2, "object" :
"statemon" , "flag" : "warning" , "data" : "FINISH = hmcontrol" }
2010-06-20 00:12:43,378 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 4, "object" :
"status" , "flag" : "warning" , "data" : "status = Eager to execute commands" }
The driveHistmem() function exit when the the command transit from STARTING to BUSY. Normally it should be like this:
2010-06-20 00:11:47,518 INFO [pool-5-thread-1] org.gumtree.gumnix.sics.internal
.io.SicsChannel:scan - Client sent: contextdo 479 hset /commands/histogram/histm
em start
2010-06-20 00:11:47,705 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 1, "object" :
"hnotify" , "flag" : "hdbevent" , "data" : { "/commands/histogram/histmem/feedback/
status ": " STARTING" } }
2010-06-20 00:11:51,096 INFO [ Thread -11] org.gumtree.gumnix.sics.internal.io.Si
csSocketListener:general - Server replied: { "con" : 171858, "trans" : 479, "objec
t ": " hset ", " flag ": " out ", " data ": " histmem stopped" }
2010-06-20 00:11:51,096 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 2, "object" :
"statemon" , "flag" : "warning" , "data" : "FINISH = histmem" }
2010-06-20 00:11:51,096 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 3, "object" :
"statemon" , "flag" : "warning" , "data" : "/commands/histogram/histmem FINISH" }
2010-06-20 00:11:53,721 INFO [ Thread -11] org.gumtree.gumnix.sics.internal.io.Si
csSocketListener:general - Server replied: { "con" : 171858, "trans" : 479, "objec
t ": " hset ", " flag ": " out ", " data ": " histmem stopped" }
2010-06-20 00:11:53,721 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 2, "object" :
"statemon" , "flag" : "warning" , "data" : "FINISH = histmem" }
2010-06-20 00:11:53,721 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 3, "object" :
"statemon" , "flag" : "warning" , "data" : "/commands/histogram/histmem FINISH" }
2010-06-20 00:11:56,456 INFO [ Thread -11] org.gumtree.gumnix.sics.internal.io.Si
csSocketListener:general - Server replied: { "con" : 171858, "trans" : 479, "objec
t ": " hset ", " flag ": " out ", " data ": " histmem stopped" }
2010-06-20 00:11:56,456 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 2, "object" :
"statemon" , "flag" : "warning" , "data" : "FINISH = histmem" }
2010-06-20 00:11:56,456 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 3, "object" :
"statemon" , "flag" : "warning" , "data" : "/commands/histogram/histmem FINISH" }
2010-06-20 00:11:59,190 INFO [ Thread -11] org.gumtree.gumnix.sics.internal.io.Si
csSocketListener:general - Server replied: { "con" : 171858, "trans" : 479, "objec
t ": " hset ", " flag ": " out ", " data ": " histmem started" }
2010-06-20 00:11:59,190 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 2, "object" :
"statemon" , "flag" : "warning" , "data" : "STARTED = histmem" }
2010-06-20 00:11:59,190 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 3, "object" :
"statemon" , "flag" : "warning" , "data" : "/commands/histogram/histmem STARTED" }
2010-06-20 00:11:59,206 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 2, "object" :
"statemon" , "flag" : "warning" , "data" : "STARTED = hmcontrol" }
2010-06-20 00:11:59,206 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 1, "object" :
"hnotify" , "flag" : "hdbevent" , "data" : { "/commands/histogram/histmem/feedback/
status ": " BUSY" } }
2010-06-20 00:12:08,596 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 1, "object" :
"hnotify" , "flag" : "hdbevent" , "data" : { "/commands/histogram/histmem/feedback/
status ": " IDLE" } }
2010-06-20 00:12:09,253 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 2, "object" :
"statemon" , "flag" : "warning" , "data" : "FINISH = hmcontrol" }
2010-06-20 00:12:09,253 INFO [ Thread -9] org.gumtree.gumnix.sics.internal.io.Sic
sSocketListener:general - Server replied: { "con" : 171855, "trans" : 4, "object" :
"status" , "flag" : "warning" , "data" : "status = Eager to execute commands" }
2010-06-20 00:12:09,690 INFO [pool-5-thread-1] org.gumtree.gumnix.sics.internal
.io.SicsChannel:general - Client sent: contextdo 3906 hset /instrument/collimato
r/att 60.0
This suggest it has problem with the java code CommandController.syncExecute()
public void syncExecute() throws SicsIOException, SicsExecutionException {
// Clear interrupt flag
SicsCore.getSicsController().clearInterrupt();
if (getStatusController() == null ) {
asyncExecute();
} else {
// Wait until command is available
while (getCommandStatus().equals(CommandStatus.BUSY)) {
sleep( "Error occured while waiting for IDLE state" );
}
// Execute
asyncExecute();
int counter = 0;
while (!statusChanged) {
sleep( "Error occured while waiting for BUSY state" );
counter += TIME_INTERVAL;
if (counter > TIME_OUT) {
throw new SicsExecutionException( "Time out on syncExecute() where status did not changed whiling execution" );
}
}
while (getCommandStatus().equals(CommandStatus.BUSY) || getCommandStatus().equals(CommandStatus.STARTING)) {
sleep( "Error occured while waiting for IDLE state" );
}
}
// Check if this device is interrupted
if (SicsCore.getSicsController().isInterrupted()) {
SicsCore.getSicsController().clearInterrupt();
throw new SicsExecutionException( "Interrupted" );
}
}
Observation:
Coming out from GumTree log:
The driveHistmem() function exit when the the command transit from STARTING to BUSY. Normally it should be like this:
This suggest it has problem with the java code CommandController.syncExecute()