select() bloqué pendant 100ms

08/10/2008 14:39 - Arnaud Meurgues :

Les traces obtenues sont les suivantes:
2008/10/08 14:50:40.647 - entering select()
2008/10/08 14:50:41.650 - called InvokeLater() from thread #4
2008/10/08 14:50:41.650 - called InvokeLater() from thread #5
2008/10/08 14:50:41.651 - exiting select()
2008/10/08 14:50:41.651 - Chrono #4: Ticks per second: 100 ;
Total ticks: 0 ; User ticks: 0 ; Sys ticks: 0 - Execute
callback
2008/10/08 14:50:41.652 - entering select()
2008/10/08 14:50:41.750 - exiting select()
2008/10/08 14:50:41.750 - Chrono #5: Ticks per second: 100 ;
Total ticks: 10 ; User ticks: 0 ; Sys ticks: 0 - Execute
callback

Chaque chrono est lié à une thread et permet de mesurer le temps entre
l'envoi dans la socket (InvokeLater()) et la réception par la main
thread (Chrono #x).
On voit que les thread #4 et #5 envoie quasi au même moment leur données
(14:50:41.650). Le premier select qui avait commencé avant l'envoi
retourne immédiatement après l'envoi de #4 et le select qui suit va
rester bloqué 100ms (10 ticks) avant de sortir.

Quelqu'un connaitrait-il la raison d'une telle latence du select() ?

Ce n'est pas bien clair. De quel type de socket s'agit-il (TCP, UDP,
Unix, autre) ?

Il se pourrait simplement que le système fasse autre chose pendant ce
temps. Évidemment si ça se produit à chaque fois que vous avez toujours
exactement 100 ms, ce n'est pas crédible. Vous pouvez tenter un coup de
strace pour essayer de voir s'il se passe des choses étranges.

Grasshoper a écrit :

Ce n'est pas bien clair. De quel type de socket s'agit-il (TCP, UDP,
Unix, autre) ?

Pardon, ce sont des sockets TCP.

Il se pourrait simplement que le système fasse autre chose pendant ce
temps.

Les traces du chrono montrent qu'aucun tick n'est passé ni en cpu user
ni en cpu system.

Évidemment si ça se produit à chaque fois que vous avez toujours
exactement 100 ms, ce n'est pas crédible.

Oui, c'est systématique.

Vous pouvez tenter un coup de
strace pour essayer de voir s'il se passe des choses étranges.

strace ? On peut lui demander de surveiller des sockets ?

J'ai mis le code de l'exemple, pour aider à la compréhension. Il n'est
pas super propre, mais le but était de constater ce problème de latence
du select().

Merci,
--
Arnaud

#include <sys/times.h>
#include <time.h>
#include <unistd.h>
#include <pthread.h>
#include <netdb.h>
#include <sys/socket.h>
#include <errno.h>
#include <signal.h>
#include <sys/ioctl.h>
#include <sys/stropts.h>
#include <sys/filio.h>
#include <iostream>
#include <list>
#include <strstream>

const int SOCKET_ERROR=-1;

class MutexLocker {
pthread_mutex_t& mutex;
public:
MutexLocker(pthread_mutex_t& m) : mutex(m) { pthread_mutex_lock(&mutex); }
~MutexLocker() { pthread_mutex_unlock(&mutex); }
};

std::string GetTime() {
struct timeval sTime;
struct tm sTimeStruct;
gettimeofday(&sTime,NULL);
localtime_r((const time_t*)&(sTime.tv_sec), &sTimeStruct);
char sTimeSpec[24];
sprintf(sTimeSpec, "%4d/%02d/%02d %02d:%02d:%02d.%03d",
sTimeStruct.tm_year + 1900,
sTimeStruct.tm_mon + 1,
sTimeStruct.tm_mday,
sTimeStruct.tm_hour,
sTimeStruct.tm_min,
sTimeStruct.tm_sec,
sTime.tv_usec / 1000
);
return sTimeSpec;
}
std::ostream& Log() {
return std::cout << GetTime() << " - ";
}
class Chronometer {
clock_t start_time;
clock_t end_time;
struct tms start_tms;
struct tms end_tms;
mutable pthread_mutex_t mutex;
std::string name;
public:
Chronometer(std::string n) : name(n),start_time(0),end_time(0) {
if (pthread_mutex_init(&mutex, NULL) != 0)
throw "Cannot init mutex";
}
void start() {
MutexLocker mlock(mutex);
start_time = times( & start_tms);
}
void stop() {
MutexLocker mlock(mutex);
end_time = times(& end_tms);
}

std::ostream& print(std::ostream& os) const {
MutexLocker mlock(mutex);
os << name << ": ";
os << "tTicks per second: " << sysconf(_SC_CLK_TCK) << " ; ";
if (start_time != 0 && end_time != 0) {
os << "tTotal ticks: " << (end_time - start_time) << " ; ";
os << "tUser ticks: " << (end_tms.tms_utime - start_tms.tms_utime)
<< " ; ";
os << "tSys ticks: " << (end_tms.tms_stime - start_tms.tms_stime);
} else
os << "No time measured";
return os;
}
~Chronometer() {
pthread_mutex_destroy(&mutex);
}
};
std::ostream& operator<< (std::ostream& os,const Chronometer& chrono) {
return chrono.print(os);
}
std::ostream& operator<< (std::ostream& os,const Chronometer* chrono) {
return chrono->print(os);
}

template <class C>
void Read(int fd,C& buf) {
int receivedSize = 0;
const int sizeToReceive = sizeof(C);

while (receivedSize != sizeToReceive) {
receivedSize += recv(fd, reinterpret_cast<char*>(&buf) + receivedSize,
sizeToReceive-receivedSize, 0);
}
// recv(fd,reinterpret_cast<char*>(&buf),sizeof(C);
}
template <class C>
void Write(int fd, C toWrite) {
C theC = toWrite;

send(fd,
&theC,
sizeof(C),
0);
}

int CreateSocket(std::string hostname, unsigned short &port) {
int socketFD = 0;

struct hostent * hp = gethostbyname(hostname.c_str());
if (hp == NULL) {
Log() << "gethostbyname() returns NULLn";
} else {
Log() << "hostname = " << hostname << 'n';
struct sockaddr_in sa;
memset(&sa, 0, sizeof(struct sockaddr_in));
sa.sin_family = hp->h_addrtype;
sa.sin_port = htons(port);
socketFD = socket(AF_INET, SOCK_STREAM, 0);
if (socketFD == SOCKET_ERROR) {
Log() << "Cannot create socketn";
socketFD = 0;
} else {
Log() << "socket createdn";
}
if (bind(socketFD,
reinterpret_cast<struct sockaddr *>(&sa),
sizeof(struct sockaddr_in)) == SOCKET_ERROR) {
close(socketFD);
Log() << "Cannot bind listen socketn";
socketFD = 0;
} else {
Log() << "socket boundn";
}
if (port == 0) {
socklen_t namelen = sizeof(struct sockaddr_in);
if (getsockname(
socketFD,
reinterpret_cast<struct sockaddr *>(&sa),
&namelen) == SOCKET_ERROR) {
close(socketFD);
throw "SOCKET_API_GETSOCKNAME";
}
port = ntohs(sa.sin_port);
}
}

return socketFD;
}

int Connect(unsigned short port) {
int socketFD;

struct hostent * hp = gethostbyname("localhost");
if (hp == NULL) {
Log() << "gethostbyname() returns NULLn";
return 0;
}
struct sockaddr_in sa;
memset(&sa, 0, sizeof(struct sockaddr_in));
memcpy(&sa.sin_addr, hp->h_addr, hp->h_length);
sa.sin_family = hp->h_addrtype;
sa.sin_port = htons(port);
socketFD = socket(AF_INET, SOCK_STREAM, 0);

if (connect(socketFD,
reinterpret_cast<struct sockaddr *>(&sa),
sizeof(struct sockaddr_in)) == SOCKET_ERROR) {
close(socketFD);
Log() << "connect failed with error #" << errno
<< ": " << strerror(errno) << 'n';
return 0;
} else {
Log() << "socket connected" << std::endl;
}
return socketFD;
}

class Socket {
int fd;
public:
Socket(unsigned short port) {
fd = Connect(port);
if (fd == 0) {
throw std::string("fail to connect loopback socket");
}
Log() << "loopback connected on #" << fd << std::endl;
}
~Socket() {
std:: cout << "closing client socket #" << fd << std::endl;
close(fd);
}
operator int() { return fd; }
};

void CallbackFunction(void *param);
class SocketServer {
SocketServer(unsigned short port=0) {
listenPort = port;
listenSocket = CreateSocket("localhost",listenPort);
if (listenSocket !=0)
Log() << "listen socket #" << listenSocket << " created on port " <<
listenPort << std::endl;
else
throw std::string("Listen socket creation failed.");
if (listen(listenSocket,5) == SOCKET_ERROR)
throw std::string("Error while listening");
}
~SocketServer() {
Log() << "closing listen socket #" << listenSocket << "n";
if (listenSocket != 0) close(listenSocket);
for (std::list<int>::const_iterator i=socketList.begin(); i !=
socketList.end(); i++) {
Log() << "closing socket #" << *i << "n";
close(*i);
}
}
void handleData(int fd) {
void* chrono;
Read(fd,chrono);
CallbackFunction(chrono);
}
void handleNewConnection() {
int connection;
connection = accept(listenSocket, NULL, NULL);
if (connection < 0)
throw std::string("Cannot accept() new connection");
socketList.push_back(connection);
}
void readSocks() {
if (FD_ISSET(listenSocket,&set))
handleNewConnection();
for (std::list<int>::const_iterator i=socketList.begin(); i !=
socketList.end(); i++) {
if (FD_ISSET(*i, &set)) {
handleData(*i);
}
}
}
void run() {
FD_ZERO(&set);
FD_SET(listenSocket, &set);
int highestFD = listenSocket;
int nbSocket;

for (std::list<int>::const_iterator i=socketList.begin(); i !=
socketList.end(); i++) {
FD_SET(*i,&set);
highestFD = (*i>highestFD) ? *i : highestFD;
}
Log() << "entering select()" << std::endl;
nbSocket = select(highestFD+1, &set, NULL, NULL, NULL);
Log() << "exiting select()" << std::endl;

if (nbSocket==SOCKET_ERROR)
throw std::string("Error in select");
if (nbSocket > 0) readSocks();
}
std::list<int> socketList;
int listenSocket;
unsigned short listenPort;
fd_set set;

public:
static SocketServer& GetSingleton() {
static SocketServer server;
return server;
}
static unsigned short GetListenPort() { return
SocketServer::GetSingleton().listenPort; }
static void Run() {
while (1) {
GetSingleton().run();
}
}
};

extern "C" void ExitOnCTRLC(int sig) {
Log() << "CTRL-C: exiting..n";
exit(0);
}

void CallbackFunction(void *param) {
Chronometer* chrono = static_cast<Chronometer*>(param);
//for (int i=0; i<10000000; ++i);
chrono->stop();
Log() << chrono << " - Execute callback" << std::endl;
}

void InvokeLater(void *param) {
static Socket sock(SocketServer::GetListenPort());

Write(static_cast<int>(sock),param);
}

extern "C" void * ThreadFunction(void*) {
Log() << "Thread startedn";
std::ostrstream name;
name << "Chrono #" << thr_self();
Chronometer *chrono = new Chronometer(name.str());
while (1) {
sleep(1);
chrono->start();
InvokeLater(chrono);
Log() << "called InvokeLater() from thread #" << thr_self() << std::endl;
}
return 0;
}

int main(int argc, char* argv[]){
signal(SIGINT,&ExitOnCTRLC);
try {
SocketServer::GetSingleton(); // ensure listen socket initialization

pthread_t thread1, thread2;
pthread_create(&thread1,0,&ThreadFunction,0);
pthread_create(&thread2,0,&ThreadFunction,0);

SocketServer::Run();
} catch (std::string &s) {
Log() << "Exception : " << s << std::endl;
}
return 0;
}

Le Wed, 08 Oct 2008 18:17:01 +0200, Arnaud Meurgues a écrit :

Vous pouvez tenter un coup de
strace pour essayer de voir s'il se passe des choses étranges.

strace ? On peut lui demander de surveiller des sockets ?

Non, c'est pour vérifier qu'il n'y a pas un appel système bloquant caché
dans le coin.

J'ai mis le code de l'exemple, pour aider à la compréhension. Il n'est
pas super propre, mais le but était de constater ce problème de latence
du select().

J'ai testé le code avec g++ 4.2.3 sous Linux et je n'observe pas le
problème que vous mentionnez.

Voici un bout de la trace d'exécution que j'obtiens :
2008/10/09 00:52:38.814 - entering select()
2008/10/09 00:52:39.817 - socket connected
2008/10/09 00:52:39.817 - loopback connected on #4
2008/10/09 00:52:39.817 - called InvokeLater() from thread #3084028816
2008/10/09 00:52:39.818 - called InvokeLater() from thread #3075640208
2008/10/09 00:52:39.818 - exiting select()
2008/10/09 00:52:39.818 - entering select()
2008/10/09 00:52:39.818 - exiting select()
2008/10/09 00:52:39.819 - Chrono #30840288160/09 00:52:38.812: Ticks per
second: 100 ; Total ticks: 0 ; User ticks: 0 ; Sys
ticks: 0 - Execute callback