Return-path: Received: from mail.gmx.net ([213.165.64.20]:42411 "HELO mail.gmx.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with SMTP id S1752614AbXLKXL3 (ORCPT ); Tue, 11 Dec 2007 18:11:29 -0500 Subject: [WIP][PATCH] rc80211_pid: Send events to userspace for debugging From: Mattias Nissler To: Stefano Brivio Cc: linux-wireless Content-Type: multipart/mixed; boundary="=-kDwgF6zsL5N4DAlUJPqL" Date: Wed, 12 Dec 2007 00:11:26 +0100 Message-Id: <1197414686.7030.27.camel@localhost> (sfid-20071211_231134_318128_5076C9EE) Mime-Version: 1.0 Sender: linux-wireless-owner@vger.kernel.org List-ID: --=-kDwgF6zsL5N4DAlUJPqL Content-Type: text/plain Content-Transfer-Encoding: 7bit Hey, this is the rc80211_pid event reporting patch that provides the data for the failed frames percentage and tx rate graphs. Instead of using syslog, I did it properly, so we can later decide whether we even want this in the tree. It's rather large, so I'm not to sure. The script that feeds the data into gnuplot is attached. It currently generates only a single plot showing failed frames percentage and tx rate over time. Note that there is more data available in the information read from the kernel, I'll add other diagrams when the need for looking at them arises :-) A sample diagram generated by the script is at http://www-user.rhrk.uni-kl.de/~nissler/rate_control_sample_graph.ps It shows approximately 3 minutes with traffic generated by my webradio stream. I'm not too happy with the result, for example, at approximately 180000, the rate control switches rate down much to drastically. I'll now update my tree with Stefanos latest patches and do some tuning and automated testing. I think I'll write a script that both runs an iperf test and generates a graph for it. Mattias This adds a new debugfs file from which rate control relevant events can be read one event per line. The output is includes the current time, so graphs can be created showing the rate control parameters. This helps in evaluating and tuning rate control parameters. Signed-off-by: Mattias Nissler --- net/mac80211/rc80211_pid.c | 346 ++++++++++++++++++++++++++++++++++++++++++++ 1 files changed, 346 insertions(+), 0 deletions(-) diff --git a/net/mac80211/rc80211_pid.c b/net/mac80211/rc80211_pid.c index baa1155..edd59df 100644 --- a/net/mac80211/rc80211_pid.c +++ b/net/mac80211/rc80211_pid.c @@ -11,6 +11,8 @@ #include #include #include +#include +#include #include #include "ieee80211_rate.h" @@ -78,6 +80,142 @@ */ #define RC_PID_TARGET_PF (20 << RC_PID_ARITH_SHIFT) + +#ifdef CONFIG_MAC80211_DEBUGFS + +enum rc_pid_event_type +{ + RC_PID_EVENT_TYPE_TX_STATUS, + RC_PID_EVENT_TYPE_RATE_CHANGE, + RC_PID_EVENT_TYPE_TX_RATE, + RC_PID_EVENT_TYPE_PF_SAMPLE, +}; + +union rc_pid_event_data +{ + /* RC_PID_EVENT_TX_STATUS */ + struct + { + struct ieee80211_tx_status tx_status; + }; + /* RC_PID_EVENT_TYPE_RATE_CHANGE */ + /* RC_PID_EVENT_TYPE_TX_RATE */ + struct + { + int index; + int rate; + }; + /* RC_PID_EVENT_TYPE_PF_SAMPLE */ + struct + { + s32 pf_sample; + s32 prop_err; + s32 int_err; + s32 der_err; + }; +}; + +struct rc_pid_event +{ + /* The time when the event occured */ + unsigned long timestamp; + + /* Event ID number */ + unsigned int id; + + /* Type of event */ + enum rc_pid_event_type type; + + /* type specific data */ + union rc_pid_event_data data; +}; + +/* Size of the event ring buffer. */ +#define RC_PID_EVENT_RING_SIZE 32 + +struct rc_pid_event_buffer +{ + /* Counter that generates event IDs */ + unsigned int ev_count; + + /* Ring buffer of events */ + struct rc_pid_event ring[RC_PID_EVENT_RING_SIZE]; + + /* Index to the entry in events_buf to be reused */ + unsigned int next_entry; + + /* Lock that guards against concurrent access to this buffer struct */ + spinlock_t lock; + + /* Wait queue for poll/select and blocking I/O */ + wait_queue_head_t waitqueue; +}; + +static void rate_control_pid_event(struct rc_pid_event_buffer *buf, + enum rc_pid_event_type type, + union rc_pid_event_data *data) +{ + struct rc_pid_event *ev; + unsigned long status; + + spin_lock_irqsave(&buf->lock, status); + ev = &(buf->ring[buf->next_entry]); + buf->next_entry = (buf->next_entry + 1) % RC_PID_EVENT_RING_SIZE; + + ev->timestamp = jiffies; + ev->id = buf->ev_count++; + ev->type = type; + ev->data = *data; + + spin_unlock_irqrestore(&buf->lock, status); + + wake_up_all(&buf->waitqueue); +} + +static void rate_control_pid_event_tx_status(struct rc_pid_event_buffer *buf, + struct ieee80211_tx_status *stat) +{ + union rc_pid_event_data evd; + + memcpy(&evd.tx_status, stat, sizeof(struct ieee80211_tx_status)); + rate_control_pid_event(buf, RC_PID_EVENT_TYPE_TX_STATUS, &evd); +} + +static void rate_control_pid_event_rate_change(struct rc_pid_event_buffer *buf, + int index, int rate) +{ + union rc_pid_event_data evd; + + evd.index = index; + evd.rate = rate; + rate_control_pid_event(buf, RC_PID_EVENT_TYPE_RATE_CHANGE, &evd); +} + +static void rate_control_pid_event_tx_rate(struct rc_pid_event_buffer *buf, + int index, int rate) +{ + union rc_pid_event_data evd; + + evd.index = index; + evd.rate = rate; + rate_control_pid_event(buf, RC_PID_EVENT_TYPE_TX_RATE, &evd); +} + +static void rate_control_pid_event_pf_sample(struct rc_pid_event_buffer *buf, + s32 pf_sample, s32 prop_err, + s32 int_err, s32 der_err) +{ + union rc_pid_event_data evd; + + evd.pf_sample = pf_sample; + evd.prop_err = prop_err; + evd.int_err = int_err; + evd.der_err = der_err; + rate_control_pid_event(buf, RC_PID_EVENT_TYPE_PF_SAMPLE, &evd); +} + +#endif + struct rc_pid_sta_info { unsigned long last_change; unsigned long last_sample; @@ -116,6 +254,15 @@ struct rc_pid_sta_info { /* Last framed failes percentage sample */ u32 last_pf; + +#ifdef CONFIG_MAC80211_DEBUGFS + /* Event buffer */ + struct rc_pid_event_buffer events; + + /* Events debugfs file entry */ + struct dentry *events_entry; +#endif + }; /* Algorithm parameters. We keep them on a per-algorithm approach, so they can @@ -165,6 +312,13 @@ static void rate_control_pid_adjust_rate(struct ieee80211_local *local, newidx += back; } + +#ifdef CONFIG_MAC80211_DEBUGFS + rate_control_pid_event_rate_change( + &((struct rc_pid_sta_info *) sta->rate_ctrl_priv)->events, + newidx, mode->rates[newidx].rate); +#endif + } static void rate_control_pid_sample(struct rc_pid_info *pinfo, @@ -204,6 +358,11 @@ static void rate_control_pid_sample(struct rc_pid_info *pinfo, err_der = pf - spinfo->last_pf; spinfo->last_pf = pf; +#ifdef CONFIG_MAC80211_DEBUGFS + rate_control_pid_event_pf_sample(&spinfo->events, pf, err_prop, err_int, + err_der); +#endif + /* Compute the controller output. */ adj = (err_prop * pinfo->coeff_p + err_int * pinfo->coeff_i + err_der * pinfo->coeff_d); @@ -237,6 +396,10 @@ static void rate_control_pid_tx_status(void *priv, struct net_device *dev, spinfo = sta->rate_ctrl_priv; spinfo->tx_num_xmit++; +#ifdef CONFIG_MAC80211_DEBUGFS + rate_control_pid_event_tx_status(&spinfo->events, status); +#endif + /* We count frames that totally failed to be transmitted as two bad * frames, those that made it out but had some retries as one good and * one bad frame. */ @@ -297,6 +460,12 @@ rate_control_pid_get_rate(void *priv, struct net_device *dev, sta_info_put(sta); sel->rate = &mode->rates[rateidx]; + +#ifdef CONFIG_MAC80211_DEBUGFS + rate_control_pid_event_tx_rate( + &((struct rc_pid_sta_info *) sta->rate_ctrl_priv)->events, + rateidx, mode->rates[rateidx].rate); +#endif } @@ -309,6 +478,9 @@ static void rate_control_pid_rate_init(void *priv, void *priv_sta, * Until that method is implemented, we will use the lowest supported * rate as a workaround. */ sta->txrate = rate_lowest_index(local, local->oper_hw_mode, sta); + +#ifdef CONFIG_MAC80211_DEBUGFS +#endif } @@ -323,6 +495,10 @@ static void *rate_control_pid_alloc(struct ieee80211_local *local) pinfo->coeff_i = RC_PID_COEFF_I; pinfo->coeff_d = RC_PID_COEFF_D; +#ifdef CONFIG_MAC80211_DEBUGFS + +#endif + return pinfo; } @@ -331,6 +507,9 @@ static void rate_control_pid_free(void *priv) { struct rc_pid_info *pinfo = priv; kfree(pinfo); + +#ifdef CONFIG_MAC80211_DEBUGFS +#endif } @@ -344,6 +523,13 @@ static void *rate_control_pid_alloc_sta(void *priv, gfp_t gfp) struct rc_pid_sta_info *spinfo; spinfo = kzalloc(sizeof(*spinfo), gfp); + if (spinfo == NULL) + return NULL; + +#ifdef CONFIG_MAC80211_DEBUGFS + spin_lock_init(&spinfo->events.lock); + init_waitqueue_head(&spinfo->events.waitqueue); +#endif return spinfo; } @@ -353,8 +539,164 @@ static void rate_control_pid_free_sta(void *priv, void *priv_sta) { struct rc_pid_sta_info *spinfo = priv_sta; kfree(spinfo); + +} + +#ifdef CONFIG_MAC80211_DEBUGFS + +struct rc_pid_events_file_info +{ + /* The event buffer we read */ + struct rc_pid_event_buffer *events; + + /* The entry we have should read next */ + unsigned int next_entry; +}; + +static int rate_control_pid_events_open(struct inode *inode, struct file *file) +{ + struct rc_pid_sta_info *sinfo = inode->i_private; + struct rc_pid_event_buffer *events = &sinfo->events; + struct rc_pid_events_file_info *file_info; + unsigned int status; + + /* Allocate a state struct */ + file_info = kmalloc(sizeof(*file_info), GFP_KERNEL); + if (file_info == NULL) + return -ENOMEM; + + spin_lock_irqsave(&events->lock, status); + + file_info->next_entry = events->next_entry; + file_info->events = events; + + spin_unlock_irqrestore(&events->lock, status); + + file->private_data = file_info; + + return 0; +} + +static int rate_control_pid_events_release(struct inode *inode, + struct file *file) +{ + struct rc_pid_events_file_info *file_info = file->private_data; + + kfree(file_info); + + return 0; +} + +static unsigned int rate_control_pid_events_poll(struct file *file, + poll_table *wait) +{ + struct rc_pid_events_file_info *file_info = file->private_data; + + poll_wait(file, &file_info->events->waitqueue, wait); + + return POLLIN | POLLRDNORM; +} + +#define RC_PID_PRINT_BUF_SIZE 64 + +static ssize_t rate_control_pid_events_read(struct file *file, char __user *buf, + size_t length, loff_t *offset) +{ + struct rc_pid_events_file_info *file_info = file->private_data; + struct rc_pid_event_buffer *events = file_info->events; + struct rc_pid_event *ev; + char pb[RC_PID_PRINT_BUF_SIZE]; + int ret; + int p; + unsigned int status; + + /* Check if there is something to read. */ + if (events->next_entry == file_info->next_entry) { + if (file->f_flags & O_NONBLOCK) + return -EAGAIN; + + /* Wait */ + ret = wait_event_interruptible(events->waitqueue, + events->next_entry != file_info->next_entry); + + if (ret) + return ret; + } + + /* Write out one event per call. I don't care whether it's a little + * inefficient, this is debugging code anyway. */ + spin_lock_irqsave(&events->lock, status); + + /* Get an event */ + ev = &(events->ring[file_info->next_entry]); + file_info->next_entry = (file_info->next_entry + 1) % + RC_PID_EVENT_RING_SIZE; + + /* Print information about the event. Note that userpace needs to + * provide large enough buffers. */ + length = length < RC_PID_PRINT_BUF_SIZE ? + length : RC_PID_PRINT_BUF_SIZE; + p = snprintf(pb, length, "%u %lu ", ev->id, ev->timestamp); + switch (ev->type) { + case RC_PID_EVENT_TYPE_TX_STATUS: + p += snprintf(pb + p, length - p, "tx_status %u %u", + ev->data.tx_status.excessive_retries, + ev->data.tx_status.retry_count); + break; + case RC_PID_EVENT_TYPE_RATE_CHANGE: + p += snprintf(pb + p, length - p, "rate_change %d %d", + ev->data.index, ev->data.rate); + break; + case RC_PID_EVENT_TYPE_TX_RATE: + p += snprintf(pb + p, length - p, "tx_rate %d %d", + ev->data.index, ev->data.rate); + break; + case RC_PID_EVENT_TYPE_PF_SAMPLE: + p += snprintf(pb + p, length - p, + "pf_sample %d %d %d %d", + ev->data.pf_sample, ev->data.prop_err, + ev->data.int_err, ev->data.der_err); + break; + } + p += snprintf(pb + p, length - p, "\n"); + + spin_unlock_irqrestore(&events->lock, status); + + if (copy_to_user(buf, pb, p)) + return -EFAULT; + + return p; } +#undef RC_PID_PRINT_BUF_SIZE + +struct file_operations rc_pid_fop_events = { + .owner = THIS_MODULE, + .read = rate_control_pid_events_read, + .poll = rate_control_pid_events_poll, + .open = rate_control_pid_events_open, + .release = rate_control_pid_events_release, +}; + +static void rate_control_pid_add_sta_debugfs(void *priv, void *priv_sta, + struct dentry *dir) +{ + struct rc_pid_sta_info *spinfo = priv_sta; + + spinfo->events_entry = debugfs_create_file("rc_pid_events", S_IRUGO, + dir, spinfo, + &rc_pid_fop_events); +} + +static void rate_control_pid_remove_sta_debugfs(void *priv, void *priv_sta) +{ + struct rc_pid_sta_info *spinfo = priv_sta; + + debugfs_remove(spinfo->events_entry); +} + +#endif + struct rate_control_ops mac80211_rcpid = { .name = "pid", .tx_status = rate_control_pid_tx_status, @@ -365,4 +707,8 @@ struct rate_control_ops mac80211_rcpid = { .free = rate_control_pid_free, .alloc_sta = rate_control_pid_alloc_sta, .free_sta = rate_control_pid_free_sta, +#ifdef CONFIG_MAC80211_DEBUGFS + .add_sta_debugfs = rate_control_pid_add_sta_debugfs, + .remove_sta_debugfs = rate_control_pid_remove_sta_debugfs, +#endif }; -- 1.5.3.4 --=-kDwgF6zsL5N4DAlUJPqL Content-Disposition: attachment; filename=make_pid_graph.py Content-Type: text/x-python; name=make_pid_graph.py; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit #!/usr/bin/python # # Feed an rc80211_pid events file into gnuplot to create a nice graph. # import os import sys import subprocess import optparse # configurable options options = optparse.Values() options.arith_scale_factor = float(256) options.graph_width = None options.graph_height = 10 options.units_per_jiffy = 0.001 options.events_file_name = None options.output_file_name = '-' options.gnuplot_path = '/usr/bin/gnuplot' def plot_frames_rate_graph(gpo, events): # configure the axes gpo.write('set xlabel "Time [jiffies]"\n') gpo.write('set xrange [0:%f]\n' % events[-1][1]) gpo.write('set ylabel "Failed frames [%]"\n') gpo.write('set yrange [0:50]\n') gpo.write('set y2label "TX rate [Mbit/s]\n') gpo.write('set y2range [0:60]\n') gpo.write('plot "-" axes x1y1 title "failed frames percentage" with linespoints,') gpo.write('"-" axes x1y2 title "TX rate" with linespoints\n') for e in filter(lambda x: x[2] == 'pf_sample', events): gpo.write('%f %f\n' % (float(e[1]), float(e[3]) / options.arith_scale_factor)) gpo.write('e\n'); for e in filter(lambda x: x[2] == 'tx_rate', events): gpo.write('%f %f\n' % (float(e[1]), float(e[4]) / 10.0)) gpo.write('e\n'); def parse_options(): parser = optparse.OptionParser() parser.add_option('-i', '--infile', dest='events_file_name', help='rc80211_pid event dump file') parser.add_option('-o', '--outfile', dest='output_file_name', help='Output file to which graph is written') parser.add_option('-y', '--height', type='int', dest='graph_height', help='Width of the diagram') parser.add_option('-x', '--width', type='int', dest='graph_width', help='Height of the diagram') parser.parse_args(sys.argv[1:], options) parser.destroy() def main(): # Parse options parse_options(); # read the input if options.events_file_name is None: eventsfile = sys.stdin else: eventsfile = open(options.events_file_name, 'r') events = map(lambda x: x.split(), eventsfile.readlines()) eventsfile.close() if len(events) == 0: raise 'No input!' # calculate time interval time_start = int(events[0][1]) time_end = int(events[-1][1]) time_diff = time_end - time_start # normalize time for e in events: e[1] = int(e[1]) - time_start # open a pipe to gnuplot gpp = subprocess.Popen(options.gnuplot_path, stdin=subprocess.PIPE) gpo = gpp.stdin # configure the gnuplot output if options.graph_width is None: options.graph_width = time_diff * options.units_per_jiffy gpo.write('set terminal postscript color lw 0.1 size %fcm, %fcm font "Helvetica" 9\n' % (options.graph_width, options.graph_height)) gpo.write('set output "%s"\n' % options.output_file_name) # plot the graphs gpo.write('set multiplot layout 1,1 columnsfirst downwards\n') plot_frames_rate_graph(gpo, events); gpo.write('unset multiplot\n') # done! gpo.close() if __name__ == '__main__': main() --=-kDwgF6zsL5N4DAlUJPqL--