Commit 05650a8b authored by Mike Hibler's avatar Mike Hibler

Add event tracing code so we can see what goes on in frisbee

parent 3233acc3
......@@ -15,7 +15,7 @@ all: frisbee frisbeed
include $(TESTBED_SRCDIR)/GNUmakerules
SHAREDOBJS = log.o network.o utils.o
SHAREDOBJS = log.o network.o trace.o utils.o
PTHREADCFLAGS = -D_THREAD_SAFE \
-I/usr/local/include/pthread/linuxthreads
PTHREADLIBS = -L/usr/local/lib -llthread -llgcc_r
......@@ -41,9 +41,10 @@ frisbeed: $(SERVEROBJS)
cp frisbeed frisbeed.debug
strip frisbeed
client.o: decls.h log.h
server.o: decls.h log.h
client.o: decls.h log.h trace.h
server.o: decls.h log.h trace.h
log.o: decls.h log.h
trace.o: decls.h trace.h log.h
install: $(INSTALL_SBINDIR)/frisbeed
......
......@@ -24,8 +24,10 @@
#include <stdarg.h>
#include <pthread.h>
#include "decls.h"
#include "trace.h"
int debug = 0;
int tracing = 0;
int portnum;
struct in_addr mcastaddr;
struct in_addr mcastif;
......@@ -102,7 +104,7 @@ main(int argc, char **argv)
int ch, slice = 0;
char *filename;
while ((ch = getopt(argc, argv, "dhp:m:s:i:")) != -1)
while ((ch = getopt(argc, argv, "dhp:m:s:i:t")) != -1)
switch(ch) {
case 'd':
debug++;
......@@ -124,6 +126,10 @@ main(int argc, char **argv)
slice = atoi(optarg);
break;
case 't':
tracing++;
break;
case 'h':
case '?':
default:
......@@ -142,7 +148,19 @@ main(int argc, char **argv)
ClientLogInit();
ImageUnzipInit(filename, slice, debug);
ClientNetInit();
if (tracing) {
ClientTraceInit("frisbee");
TraceStart(tracing);
}
PlayFrisbee();
if (tracing) {
TraceStop();
TraceDump();
}
exit(0);
}
......@@ -210,6 +228,8 @@ ClientRecvThread(void *arg)
case PKTSUBTYPE_LEAVE:
case PKTSUBTYPE_REQUEST:
/* Ignore these. They are from other clients. */
CLEVENT(3, EV_OCLIMSG,
p->hdr.srcip, p->hdr.subtype, 0, 0);
break;
default:
......@@ -361,6 +381,7 @@ GotBlock(Packet_t *p)
* packet if there is no free chunk.
*/
if (free == -1) {
CLEVENT(2, EV_CLINOROOM, chunk, block, 0, 0);
DOSTAT(nofreechunks++);
if (debug)
log("No more free buffer slots for chunk %d!",
......@@ -372,6 +393,7 @@ GotBlock(Packet_t *p)
* Was this chunk already processed?
*/
if (ChunkBitmap[chunk]) {
CLEVENT(2, EV_CLIDUPCHUNK, chunk, block, 0, 0);
DOSTAT(dupchunk++);
if (0)
log("Duplicate chunk %d ignored!", chunk);
......@@ -398,6 +420,7 @@ GotBlock(Packet_t *p)
* we do not need it (cause of broadcast/multicast).
*/
if (ChunkBuffer[i].bitmap[block]) {
CLEVENT(2, EV_CLIDUPBLOCK, chunk, block, 0, 0);
DOSTAT(dupblock++);
if (0)
log("Duplicate block %d in chunk %d", block, chunk);
......@@ -407,6 +430,7 @@ GotBlock(Packet_t *p)
ChunkBuffer[i].blockcount--;
memcpy(ChunkBuffer[i].blocks[block].data, p->msg.block.buf, BLOCKSIZE);
LastReceiveChunk = chunk;
CLEVENT(2, EV_CLIBLOCK, chunk, block, ChunkBuffer[i].blockcount, 0);
/*
* Anytime we receive a packet thats needed, reset the idle counter.
......@@ -418,6 +442,7 @@ GotBlock(Packet_t *p)
* Is the chunk complete? If so, then release it to the main thread.
*/
if (ChunkBuffer[i].blockcount == 0) {
CLEVENT(1, EV_CLICHUNK, chunk, 0, 0, 0);
if (debug)
log("Releasing chunk %d to main thread", chunk);
ChunkBuffer[i].ready = 1;
......@@ -451,6 +476,7 @@ RequestRange(int chunk, int block, int count)
p->msg.request.block = block;
p->msg.request.count = count;
PacketSend(p);
CLEVENT(1, EV_CLIREQ, chunk, block, count, 0);
}
static void
......@@ -458,6 +484,8 @@ RequestChunk(int timedout)
{
int i, j, k;
CLEVENT(1, EV_CLIREQCHUNK, timedout, 0, 0, 0);
/*
* Look for unfinished chunks.
*/
......
......@@ -28,7 +28,7 @@
#define MCAST_TTL 5
static int sock;
static struct in_addr ipaddr;
struct in_addr myipaddr;
static void
CommonInit(void)
......@@ -131,7 +131,7 @@ CommonInit(void)
if ((he = gethostbyname(buf)) == 0)
fatal("gethostbyname: %s", hstrerror(h_errno));
memcpy((char *)&ipaddr, he->h_addr, sizeof(ipaddr));
memcpy((char *)&myipaddr, he->h_addr, sizeof(myipaddr));
}
int
......@@ -193,7 +193,7 @@ PacketSend(Packet_t *p)
int len;
len = sizeof(p->hdr) + p->hdr.datalen;
p->hdr.srcip = ipaddr.s_addr;
p->hdr.srcip = myipaddr.s_addr;
to.sin_family = AF_INET;
to.sin_port = htons(portnum);
......@@ -231,7 +231,7 @@ PacketReply(Packet_t *p)
to.sin_family = AF_INET;
to.sin_port = htons(portnum);
to.sin_addr.s_addr = p->hdr.srcip;
p->hdr.srcip = ipaddr.s_addr;
p->hdr.srcip = myipaddr.s_addr;
while (sendto(sock, (void *)p, len, 0,
(struct sockaddr *)&to, sizeof(to)) < 0) {
......
......@@ -24,8 +24,11 @@
#include "decls.h"
#include "queue.h"
#include "trace.h"
/* Globals */
int debug = 0;
int tracing = 0;
int portnum;
struct in_addr mcastaddr;
struct in_addr mcastif;
......@@ -107,6 +110,8 @@ WorkQueueEnqueue(int chunk, int block, int blockcount)
queue_enter(&WorkQ, wqel, WQelem_t *, chain);
pthread_mutex_unlock(&WorkQLock);
EVENT(1, EV_WORKENQ, mcastaddr, chunk, block, blockcount, 0);
return 1;
}
......@@ -134,6 +139,8 @@ WorkQueueDequeue(int *chunk, int *block, int *blockcount)
free(wqel);
pthread_mutex_unlock(&WorkQLock);
EVENT(1, EV_WORKDEQ, mcastaddr, *chunk, *block, *blockcount, 0);
return 1;
}
......@@ -156,10 +163,12 @@ ClientJoin(Packet_t *p)
/*
* Return fileinfo. Duplicates are harmless.
*/
EVENT(1, EV_JOINREQ, ipaddr, clientid, 0, 0, 0);
p->hdr.type = PKTTYPE_REPLY;
p->hdr.datalen = sizeof(p->msg.join);
p->msg.join.blockcount = FileInfo.blocks;
PacketReply(p);
EVENT(1, EV_JOINREP, ipaddr, FileInfo.blocks, 0, 0, 0);
/*
* Log after we send reply so that we get the packet off as
......@@ -178,6 +187,9 @@ ClientLeave(Packet_t *p)
{
struct in_addr ipaddr = { p->hdr.srcip };
EVENT(1, EV_LEAVEMSG, ipaddr,
p->msg.leave.clientid, p->msg.leave.elapsed, 0, 0);
log("%s (id %u) leaves at %s! Reports %d elapsed seconds.",
inet_ntoa(ipaddr), p->msg.leave.clientid, CurrentTimeString(),
p->msg.leave.elapsed);
......@@ -197,6 +209,7 @@ ClientRequest(Packet_t *p)
int count = p->msg.request.count;
int enqueued;
EVENT(1, EV_REQMSG, ipaddr, chunk, block, count, 0);
if (block + count > CHUNKSIZE)
fatal("Bad request from %s - chunk:%d block:%d size:%d",
inet_ntoa(ipaddr), chunk, block, count);
......@@ -315,6 +328,8 @@ PlayFrisbee(void)
pfatal("Reading File");
fatal("EOF on file");
}
EVENT(2, EV_READFILE, mcastaddr,
offset, readsize, cc, 0);
if (cc != readsize)
fatal("Short read: %d!=%d", cc, readsize);
......@@ -329,6 +344,8 @@ PlayFrisbee(void)
BLOCKSIZE);
PacketSend(p);
EVENT(3, EV_BLOCKMSG, mcastaddr,
chunk, block+j, 0, 0);
}
offset += readsize;
block += readcount;
......@@ -364,7 +381,7 @@ main(int argc, char **argv)
pthread_t child_pid;
off_t fsize;
while ((ch = getopt(argc, argv, "dhp:m:i:")) != -1)
while ((ch = getopt(argc, argv, "dhp:m:i:t")) != -1)
switch(ch) {
case 'd':
debug++;
......@@ -381,6 +398,9 @@ main(int argc, char **argv)
case 'i':
inet_aton(optarg, &mcastif);
break;
case 't':
tracing++;
break;
case 'h':
case '?':
default:
......@@ -426,6 +446,11 @@ main(int argc, char **argv)
*/
ServerNetInit();
if (tracing) {
ServerTraceInit("frisbeed");
TraceStart(tracing);
}
/*
* Create the subthread to listen for packets.
*/
......@@ -436,6 +461,11 @@ main(int argc, char **argv)
PlayFrisbee();
if (tracing) {
TraceStop();
TraceDump();
}
/*
* Exit from main thread will kill all the children.
*/
......@@ -450,6 +480,11 @@ main(int argc, char **argv)
void
quit(int sig)
{
if (tracing) {
TraceStop();
TraceDump();
}
log("Caught signal %d. Exiting ...", sig);
exit(0);
}
......@@ -460,6 +495,11 @@ quit(int sig)
void
reinit(int sig)
{
if (tracing) {
TraceStop();
TraceDump();
}
log("Caught signal %d. Exiting ...", sig);
exit(1);
}
......
#include <stdio.h>
#include <stdlib.h>
#include <fcntl.h>
#include <netinet/in.h>
#include <arpa/inet.h>
#include "decls.h"
#include "trace.h"
#include "log.h"
#ifdef NEVENTS
struct event eventlog[NEVENTS];
struct event *evptr = eventlog;
struct event *evend = &eventlog[NEVENTS];
int evlogging, evcount;
pthread_mutex_t evlock;
static int evisclient;
static FILE *fd;
static void
TraceInit(char *file)
{
if (file) {
fd = fopen(file, "a+");
if (fd == NULL)
pfatal("Cannot open logfile %s", file);
} else
fd = stderr;
pthread_mutex_init(&evlock, 0);
}
void
ClientTraceInit(char *file)
{
extern struct in_addr myipaddr;
if (file) {
char name[64];
snprintf(name, sizeof(name),
"%s-%s.trace", file, inet_ntoa(myipaddr));
TraceInit(name);
} else
TraceInit(0);
evisclient = 1;
}
void
ServerTraceInit(char *file)
{
extern struct in_addr myipaddr;
if (file) {
char name[64];
snprintf(name, sizeof(name),
"%s-%s.trace", file, inet_ntoa(myipaddr));
TraceInit(name);
} else
TraceInit(0);
evisclient = 0;
}
void
TraceStart(int level)
{
evlogging = level;
}
void
TraceStop(void)
{
evlogging = 0;
}
#define timevalsub(vvp, uvp) \
do { \
(vvp)->tv_sec -= (uvp)->tv_sec; \
(vvp)->tv_usec -= (uvp)->tv_usec; \
if ((vvp)->tv_usec < 0) { \
(vvp)->tv_sec--; \
(vvp)->tv_usec += 1000000; \
} \
} while (0)
void
TraceDump(void)
{
struct event *ptr;
int done = 0;
struct timeval startt, stamp;
int oevlogging = evlogging;
evlogging = 0;
ptr = evptr;
do {
if (ptr->event > 0 && ptr->event <= EV_MAX) {
if (!done) {
done = 1;
fprintf(fd, "%d events, start: %ld.%02ld:\n",
evcount > NEVENTS ? NEVENTS : evcount,
(long)ptr->tstamp.tv_sec,
ptr->tstamp.tv_usec/10000);
startt = ptr->tstamp;
}
stamp = ptr->tstamp;
timevalsub(&stamp, &startt);
fprintf(fd, " +%04ld.%02ld: ",
(long)stamp.tv_sec, stamp.tv_usec/10000);
switch (ptr->event) {
case EV_JOINREQ:
fprintf(fd, "%s: JOIN request, ID=%lx\n",
inet_ntoa(ptr->srcip), ptr->args[0]);
break;
case EV_JOINREP:
fprintf(fd, "%s: JOIN reply, blocks=%lu\n",
inet_ntoa(ptr->srcip), ptr->args[0]);
break;
case EV_LEAVEMSG:
fprintf(fd, "%s: LEAVE msg, ID=%lx, time=%lu\n",
inet_ntoa(ptr->srcip),
ptr->args[0], ptr->args[1]);
break;
case EV_REQMSG:
fprintf(fd, "%s: REQUEST msg, %lu@%lu/%lu\n",
inet_ntoa(ptr->srcip), ptr->args[2],
ptr->args[0], ptr->args[1]);
break;
case EV_BLOCKMSG:
fprintf(fd, "send block, %lu/%lu\n",
ptr->args[0], ptr->args[1]);
break;
case EV_WORKENQ:
fprintf(fd, "enqueues, %lu@%lu/%lu\n",
ptr->args[2],
ptr->args[0], ptr->args[1]);
break;
case EV_WORKDEQ:
fprintf(fd, "dequeues, %lu@%lu/%lu\n",
ptr->args[2],
ptr->args[0], ptr->args[1]);
break;
case EV_READFILE:
fprintf(fd, "readfile, %lu@%lu -> %lu\n",
ptr->args[1],
ptr->args[0], ptr->args[2]);
break;
case EV_OCLIMSG:
{
struct in_addr ipaddr = { ptr->args[0] };
fprintf(fd, "%s: got %s msg, ",
inet_ntoa(ptr->srcip),
(ptr->args[1] == PKTSUBTYPE_JOIN ?
"JOIN" :
(ptr->args[1] == PKTSUBTYPE_LEAVE ?
"LEAVE" : "REQUEST")));
fprintf(fd, "ip=%s\n", inet_ntoa(ipaddr));
break;
}
case EV_CLINOROOM:
fprintf(fd, "%s: block %lu/%lu, no room\n",
inet_ntoa(ptr->srcip),
ptr->args[0], ptr->args[1]);
break;
case EV_CLIDUPCHUNK:
fprintf(fd, "%s: block %lu/%lu, dup chunk\n",
inet_ntoa(ptr->srcip),
ptr->args[0], ptr->args[1]);
break;
case EV_CLIDUPBLOCK:
fprintf(fd, "%s: block %lu/%lu, dup block\n",
inet_ntoa(ptr->srcip),
ptr->args[0], ptr->args[1]);
break;
case EV_CLIBLOCK:
fprintf(fd, "%s: block %lu/%lu, bcount=%lu\n",
inet_ntoa(ptr->srcip),
ptr->args[0], ptr->args[1],
ptr->args[2]);
break;
case EV_CLICHUNK:
fprintf(fd, "%s: got chunk %lu\n",
inet_ntoa(ptr->srcip), ptr->args[0]);
break;
case EV_CLIREQ:
fprintf(fd, "%s: send REQUEST, %lu@%lu/%lu\n",
inet_ntoa(ptr->srcip), ptr->args[2],
ptr->args[0], ptr->args[1]);
break;
case EV_CLIREQCHUNK:
fprintf(fd, "%s: request chunk, timeo=%lu\n",
inet_ntoa(ptr->srcip), ptr->args[0]);
break;
}
}
if (++ptr == evend)
ptr = eventlog;
} while (ptr != evptr);
fflush(fd);
evlogging = oevlogging;
}
#endif
#include <pthread.h>
#include <sys/time.h>
#include <netinet/in.h>
//#define NEVENTS 5000
#ifdef NEVENTS
struct event {
struct timeval tstamp;
struct in_addr srcip;
int event;
unsigned long args[4];
};
extern struct event eventlog[];
extern struct event *evptr, *evend;
extern int evlogging, evcount;
extern pthread_mutex_t evlock;
#define EVENT(l, e, ip, a1, a2, a3, a4) \
if (evlogging >= (l)) { \
pthread_mutex_lock(&evlock); \
gettimeofday(&evptr->tstamp, 0); \
evptr->event = (e); \
evptr->srcip = (ip); \
evptr->args[0] = (unsigned long)(a1); \
evptr->args[1] = (unsigned long)(a2); \
evptr->args[2] = (unsigned long)(a3); \
evptr->args[3] = (unsigned long)(a4); \
if (++evptr == evend) evptr = eventlog; \
evcount++; \
pthread_mutex_unlock(&evlock); \
}
#define CLEVENT(l, e, a1, a2, a3, a4) \
if (evlogging >= (l)) { \
extern struct in_addr myipaddr; \
pthread_mutex_lock(&evlock); \
gettimeofday(&evptr->tstamp, 0); \
evptr->event = (e); \
evptr->srcip = myipaddr; \
evptr->args[0] = (unsigned long)(a1); \
evptr->args[1] = (unsigned long)(a2); \
evptr->args[2] = (unsigned long)(a3); \
evptr->args[3] = (unsigned long)(a4); \
if (++evptr == evend) evptr = eventlog; \
evcount++; \
pthread_mutex_unlock(&evlock); \
}
#define EV_JOINREQ 1
#define EV_JOINREP 2
#define EV_LEAVEMSG 3
#define EV_REQMSG 4
#define EV_BLOCKMSG 5
#define EV_WORKENQ 6
#define EV_WORKDEQ 7
#define EV_READFILE 8
#define EV_CLIREQ 9
#define EV_OCLIMSG 10
#define EV_CLINOROOM 11
#define EV_CLIDUPCHUNK 12
#define EV_CLIDUPBLOCK 13
#define EV_CLIBLOCK 14
#define EV_CLICHUNK 15
#define EV_CLIREQCHUNK 16
#define EV_MAX 16
extern void ClientTraceInit(char *file);
extern void ServerTraceInit(char *file);
extern void TraceStart(int level);
extern void TraceStop(void);
extern void TraceDump(void);
#else
#define EVENT(l, e, ip, a1, a2, a3, a4)
#define CLEVENT(l, e, a1, a2, a3, a4)
#define ClientTraceInit(file)
#define ServerTraceInit(file)
#define TraceStart(level)
#define TraceStop()
#define TraceDump()
#endif
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment