[RFC] Android Logger vs. Shared Memory FIGHT!

[RFC] Android Logger vs. Shared Memory FIGHT!

[Daniel Walker]

	I went to Linaro Connect a few weeks ago. While I was there they held a
meeting with some of the Android developers and some community developers.
During the meeting Brian Swetland and Tim Bird were talking about upstreaming
Android's logger kernel changes. Brian mentioned that logger was in the kernel
for “performance reasons”. Then later Zach Pfeffer asked if Google had a test
suite for binder. They said they didn't have anything like that, which I thought
was really surprising. From that I assume there is no test suite for logger and
I doubt they have any performance analysis either.

	Since logger has a relatively simple interface I felt it would be a good
target for performance analysis (compared to something like binder). After
analyzing logger for a little while I decided it would be relatively easy to
create something similar with shared memory.

	The test case that I created uses a POSIX shared memory area as the
storage medium. This area is different than normal shared memory in that it's
visible as a file under /dev/shm/ . The shared memory area is protected with a
System V semaphore. The semaphore is really overkill since contention isn't very
likely in a real Android logging case. The writers are expected to manage the
shared area when doing writes. This allows the logging to be daemon-less.

	I tried to make the test as much apples to apples as possible. It is somewhat 
difficult since logger is doing a fair amount of stuff in kernel space which may not
be needed in userspace, or is difficult to replicate. The read side is typically used 
infrequently and I don't think performance really matters in that case. I only really 
address the write side, however my test case includes readers for both (not fully
tested).

The test case was run on both x86 and ARM. Results below all in Bytes per second,

x86:
+-----------------+----------------------+-------------------+ 
|Clocksource      |         TSC          |       ACPI_PM     |
+-----------------+----------------------+-------------------+
|Shared Memory    |     457172567.4B/s   |     28708407.6B/s |
+-----------------+----------------------+-------------------+
|Android Logger   |      77531671.5B/s   |     79575677.3B/s |
+-----------------+----------------------+-------------------+ 

ARM:
+-----------------+----------------------+
|Shared Memory    |    15336338.6B/s     |
+-----------------+----------------------+
|Android Logger   |     6615796.3B/s     |
+-----------------+----------------------+

	The x86 machine was a single core AMD 1.8Ghz machine, and the ARM was a G1
phone with an MSM7201a SoC using a v3.3 kernel in all cases. I also used chrt to
elevate the priority of the test case above all other processes in the system. The
test case was run three time and averaged. The source for the test case is below.

Noticeably absent is an hpet test. I didn't have one available.

Conclusions,

	The speed of logger isn't really dependent on the clocksource. There
is very little change between the two clocksource runs on x86 for logger. It's because
the bottle neck for logger isn't getting the time. The shared memory version does
depend heavily on the speed of the clocksource. Shared memory with an ACPI_PM
clocksource is about %64 slower than logger. In the TSC case the shared memory version
is about %490 faster. The TSC is fast, but using VDSO it's even better.

	On ARM it's more straight forward with the Shared Memory version being about
%132 faster than logger.

	As you can see there are some trade offs on x86. I should note that there are
Android phones being made with x86 platforms. So this isn't as ridiculous as it might
seem. I would guess most of those phones don't have ACPI_PM clocks however.

	I made no attempt to address any security issues in logger. Since logger has
no security built into it currently. There are at least two ways to provide security
to the shared memory interface that I know of, but I'm not planning to discuss them in
this analysis.

I welcome comments on the test case, or my analysis.
 
Here's the test case used,


/*
 * Copyright (c) 2012, Daniel Walker <dwalker@fifo99.com>
 *
 * gcc -O2 logger_test.c -lrt -lpthread -o logger_test
 *
 */
#include <stdio.h>
#include <unistd.h>
#include <stdlib.h>
#include <string.h>
#include <signal.h>

#include <fcntl.h>
#include <time.h>
#include <pthread.h>
#include <errno.h>

#include <stdint.h>
#include <semaphore.h>
#include <sys/mman.h>
#include <sys/types.h>
#include <sys/time.h>
#include <sys/stat.h>
#include <sys/uio.h>

char buffer[1024] = { [0 ... 1023] = '0' };

struct timeval tv1, tv2;

struct memory_control_area {
	sem_t mutex;
	unsigned long start, end, size, readers;
	_Bool overwrite;
	char data[0];
};

_Bool stopped = 0;

#define READ_WAIT_FIFO_NAME	"/tmp/shared_memory_reader_fifo"
int read_wait_fifo;

void alarm_handler(int signal)
{
	stopped = 1;
}

struct sigaction alarm_overload = {
	.sa_handler = alarm_handler,
};

void int_handler(int signal)
{
	stopped = 1;
}

struct sigaction int_overload = {
	.sa_handler = int_handler,
};

/*
 *  This is for compatibility with Android logger
 */
#define CONTENT_LINES (64)

/*
 *  Size of the memory area. This is minus the control structure.
 */
#define CONTENT_SIZE (CONTENT_LINES*1024 - sizeof(struct memory_control_area))

/*
 * Subtracts tv1 from tv2 and prints the output.
 */
void print_diff_time(char header[], struct timeval *tv1, struct timeval *tv2, unsigned long long bytes)
{
	unsigned long long diff_useconds, diff_seconds;
	double total_time;

	diff_useconds = (tv2->tv_usec + (tv2->tv_sec*1000000)) -
			(tv1->tv_usec + (tv1->tv_sec*1000000)),

	total_time = diff_useconds/1000000.0;

	printf("%s wrote %llu bytes in %.1f seconds at a rate of %.1f Bytes/second\n",
		header, bytes, total_time, (double)(bytes/total_time));
}

char *sample_log_string(void)
{
	/*
	 *  Just some sample logs for effect.
	 */
	static char *sample_msgs[16] = {
		"New MMC card '00000' (serial 2029453699) added @ /devices/platform/msm_sdcc.2/mmc_host/mmc1/mmc1:0001\n",
		"Disk (blkdev 179:0), 7954432 secs (3884 MB) 1 partitions\n",
		"New blkdev 179.0 on media 00000, media path /devices/platform/msm_sdcc.2/mmc_host/mmc1/mmc1:0001, Dpp 1\n",
		"Partition (blkdev 179:1), 7946240 secs (3880 MB) type 0xb\n",
		"New blkdev 179.1 on media 00000, media path /devices/platform/msm_sdcc.2/mmc_host/mmc1/mmc1:0001, Dpp 0\n",
		"Evaluating dev '/devices/platform/msm_sdcc.2/mmc_host/mmc1/mmc1:0001/block/mmcblk0' for mountable filesystems for '/sdcard'\n",
		"handle_switch_event(): Ignoring switch 'No Device'\n",
		"Bootstrapping complete\n",
		"dosfsck 3.0.1 (23 Nov 2008)\n",
		"akmd 1.6.4 START \n",
		"library version: 1.2.1.1129\n",
		"dosfsck 3.0.1, 23 Nov 2008, FAT32, LFN\n",
		"Logical sector size is zero.\n",
		"/system/bin/dosfsck terminated by exit(8)\n",
		"Filesystem check failed (not a FAT filesystem)\n",
		"vfat filesystem check failed on 179:1 (No data available)\n",
	};

	static index = 0;
	
	if (index >= 16) {
		index = 0;
	}

	return sample_msgs[index++];
}

void register_signal_handler(int sig, struct sigaction *overload)
{
	int ret = sigaction(sig, overload, NULL);
	if (ret < 0) {
		perror("sigaction():");
		exit(1);
	}

}

enum fifo_direction {
	FIFO_READ,
	FIFO_WRITE,
};

int open_fifo(enum fifo_direction dir)
{
	int ret = open(READ_WAIT_FIFO_NAME, (dir == FIFO_READ) ? O_RDONLY : O_WRONLY);
	if (ret < 0) {
		perror("open():");
		exit(1);
	}
	
}

/*
 *  Test this kernels logger interface in /dev/log/
 */
void test_logger(int seconds)
{
	int fd, i, ret, prio = 4;
	unsigned long long bytes_written = 0;
	const char *tag = "";
	unsigned long long j;
    	struct iovec vec[3];

	gettimeofday(&tv1, NULL);

	fd = open("/dev/log_main", O_WRONLY);
	if (fd < 0) {
		perror("open():");
		exit(1);
	}
	
	stopped = 0;

	alarm(seconds);

	vec[0].iov_base	= (unsigned char *) &prio;
	vec[0].iov_len	= 1;
	vec[1].iov_base	= (void *) tag;
	vec[1].iov_len	= 1;

	while (!stopped) {
		char *buffer = sample_log_string();

		vec[2].iov_base	= (void *) buffer;
		vec[2].iov_len	= strlen(buffer); /* Don't include the null */

		ret = writev(fd, vec, 3);
		if (ret < 0) {
			perror("writev():");
			exit(1);
		}
		bytes_written += ret;
	}

	close(fd);

	gettimeofday(&tv2, NULL);

	print_diff_time("Android logger", &tv1, &tv2, bytes_written);	
}

void logger_reader()
{
	char buffer[1024];
	struct logger_entry {
	    uint16_t    len;    /*  length of the payload */
	    uint16_t    __pad;  /*  no matter what, we get 2 bytes of padding */
	    int32_t     pid;    /*  generating process's pid */
	    int32_t     tid;    /*  generating process's tid */
	    int32_t     sec;    /*  seconds since Epoch */
	    int32_t     nsec;   /*  nanoseconds */
	    char        msg[0]; /*  the entry's payload */
	} *casted_buffer = (struct logger_entry *)buffer;

	int i, size, fd, prio = 0;
	struct iovec vec[3]; 
	const char *tag = "";

	vec[0].iov_base = (void *) buffer,
	vec[0].iov_len = 1024,

	fd = open("/dev/log_main", O_RDONLY);
	if (fd < 0) {
		perror("open():");
		exit(1);
	}

	while (size = readv(fd, vec, 1)) { 
		for(i = 1; i < casted_buffer->len; i++) {
			printf("%c", casted_buffer->msg[i]);
		}
	}
	close(fd);	
}

/*
 *  Test write into shared memory
 */
void test_shared_memory(int seconds)
{
	struct memory_control_area *shared_area;
	unsigned long long bytes_written = 0;
	int fd, i, ret;

	stopped = 0;

	if (seconds == 0) {
		register_signal_handler(SIGINT, &int_overload);
	} else {
		alarm(seconds);
	}

	gettimeofday(&tv1, NULL);

	fd = shm_open("/shared_memory_test", O_CREAT | O_RDWR, S_IRUSR | S_IRGRP | S_IWUSR | S_IWGRP);
	if (fd < 0) {
		perror("shm_open():");
		exit(1);
	}

	ret = ftruncate(fd, CONTENT_SIZE);
	if (ret < 0) {
		perror("ftruncate():");
		exit(1);
	}

	shared_area = (struct memory_control_area *)mmap(NULL, CONTENT_SIZE, PROT_READ | PROT_WRITE, MAP_SHARED | MAP_LOCKED, fd, 0);
	if (shared_area == MAP_FAILED) {
		perror("mmap():");
		exit(1);
	}

	while (!stopped) {
		char *buffer = sample_log_string();
		int buffer_size = strlen(buffer); /* don't write the null */
		struct timeval sample;

		sem_wait(&shared_area->mutex);
		
		/*
		 *  This isn't used but it's here for compatibility with
		 *  logger. Since logger samples the time on each write.
		 *  This can also be a delay sink depending on which clocksource
		 *  your using.
		 */
		gettimeofday(&sample, NULL);

		/*
		 *  Two cases. The first one handles when the buffer loops
		 *  around to the start, the second is just a regular write.
		 */
		if(shared_area->end + buffer_size >= CONTENT_SIZE)
		{
			unsigned long rem = CONTENT_SIZE - shared_area->end;
	
			memcpy(shared_area->data + shared_area->end, buffer, rem);

			/* Loop around to the start of the buffer */
			shared_area->end = 0;

			memcpy(shared_area->data + shared_area->end, buffer + rem, buffer_size - rem);
			
			shared_area->end = buffer_size - rem;

			shared_area->overwrite = 1;

		} else {
			memcpy(shared_area->data + shared_area->end, buffer, buffer_size);
			shared_area->end += buffer_size;
		}

		if (shared_area->overwrite)
			shared_area->start = shared_area->end + 1;

		sem_post(&shared_area->mutex);

		bytes_written += buffer_size; 
	}

	close(fd);

	gettimeofday(&tv2, NULL);

	print_diff_time("Shared memory", &tv1, &tv2, bytes_written);	

}

void init_shared_memory_file(void)
{
	struct memory_control_area *shared_area;
	int fd, ret, i;

	fd = shm_open("/shared_memory_test", O_CREAT | O_RDWR, S_IRUSR | S_IRGRP | S_IWUSR | S_IWGRP);
	if (fd < 0) {
		perror("shm_open():");
		exit(1);
	}

	ret = ftruncate(fd, CONTENT_SIZE);
	if (ret < 0) {
		perror("ftruncate():");
		exit(1);
	}

	shared_area = (struct memory_control_area *)mmap(NULL, CONTENT_SIZE, PROT_READ | PROT_WRITE, MAP_SHARED | MAP_LOCKED, fd, 0);
	if (shared_area == MAP_FAILED) {
		perror("mmap():");
		exit(1);
	}

	/* Warm up the shared memory area */
	for (i = 0; i < CONTENT_SIZE - sizeof(struct memory_control_area); i++)
		shared_area->data[i] = 0;

	sem_init(&shared_area->mutex, 1, 1);

	shared_area->readers = 0;
	shared_area->start = 0;
	shared_area->end = 0;

	close(fd);
}

void shared_memory_reader()
{
	int fd, i, ret, bytes_to_read, bytes_read = 0;
	struct memory_control_area *shared_area;
	char output_buf[1024];

	fd = shm_open("/shared_memory_test", O_CREAT | O_RDWR, S_IRUSR | S_IRGRP | S_IWUSR | S_IWGRP);
	if (fd < 0) {
		perror("shm_open():");
		exit(1);
	}

	ret = ftruncate(fd, CONTENT_SIZE);
	if (ret < 0) {
		perror("ftruncate():");
		exit(1);
	}

	shared_area = (struct memory_control_area *)mmap(NULL, CONTENT_SIZE, PROT_READ | PROT_WRITE, MAP_SHARED | MAP_LOCKED, fd, 0);
	if (shared_area == MAP_FAILED) {
		perror("mmap():");
		exit(1);
	}
	
	bytes_to_read = CONTENT_SIZE - shared_area->end;

	while (bytes_to_read) {
		if (bytes_to_read >= 1024) {
			memcpy(output_buf, shared_area->data + shared_area->end + bytes_read, 1024);
			bytes_read += 1024;
			bytes_to_read -= 1024;
		} else {
			memcpy(output_buf, shared_area->data + shared_area->end + bytes_read, bytes_to_read);
			bytes_read += bytes_to_read;
			bytes_to_read = 0;
		}
		
		for(i = 0; i < 1024; i++)
			printf("%c", output_buf[i]);	
	}
	
	bytes_to_read = shared_area->end;

	while (bytes_to_read) {
		if (bytes_to_read >= 1024) {
			memcpy(output_buf, shared_area->data + bytes_read, 1024);
			bytes_read += 1024;
			bytes_to_read -= 1024;
		} else {
			memcpy(output_buf, shared_area->data + bytes_read, bytes_to_read);
			bytes_read += bytes_to_read;
			bytes_to_read = 0;
		}

		for(i = 0; i < 1024; i++)
			printf("%c", output_buf[i]);
	}
}

int main(int argc, char *argv[])
{
	char help[] =	"Android Logger Performance Tester\n"
			"\n"
			"Options:\n"
			"-l:	Test android logger in /dev/log/ (default)\n"
			"-s:	Test shared memory in /dev/shm\n"
			"	Must be mount with a command similar to \"mount -t tmpfs none /dev/shm\"\n"
			"-n X:	Number of seconds to run the test (default 60, 0 == unlimited)\n"
			"-i:	Initialize shared memory file\n"
			"-r:	Run shared memory reader\n"
			"-t:	Run logger reader\n"
			"\n";			

	int c, ret;
	int seconds = 60;

	ret = mlockall(MCL_CURRENT | MCL_FUTURE);
	if (ret < 0) {
		perror("mlockall():");
		exit(1);
	}

	register_signal_handler(SIGALRM, &alarm_overload);

	if (access(READ_WAIT_FIFO_NAME, F_OK) < 0) {
		ret = mkfifo(READ_WAIT_FIFO_NAME, S_IWUSR | S_IWGRP | S_IRUSR | S_IRGRP);
		if (ret < 0) {
			perror("mkfifo():");
			exit(1);
		}
	}

	while ((c = getopt(argc, argv, "hiutlsrn:")) != -1)  {

		switch (c) {
			case 'h':
				printf("%s\n", help);
				break;	
			case 'u':
				if (shm_unlink("/shared_memory_test") != 0) {
					perror("shm_unlink():");
					exit(1);
				}
			case 'i':
				init_shared_memory_file();
				break;
			case 'l':
				test_logger(seconds);
				break;
			case 's':
				test_shared_memory(seconds);
				break;
			case 'r':
				shared_memory_reader();
				break;
			case 't':
				logger_reader();
				break;
			case 'n':
				errno = 0;
				seconds = strtoll(optarg, NULL, 10);
				if (errno != 0) {
					perror("strtol():");
					exit(1);
				}
		}
	}

	return 0;
}

Re: [RFC] Android Logger vs. Shared Memory FIGHT!

[Daniel Walker]

Just wanted to add a few more CC's (or at least let more people know
this went out)...

Daniel

Re: [RFC] Android Logger vs. Shared Memory FIGHT!

[Daniel Walker]

On Wed, Mar 28, 2012 at 02:06:32PM -0700, Daniel Walker wrote:
> 
> 
> 	I went to Linaro Connect a few weeks ago. While I was there they held a
> meeting with some of the Android developers and some community developers.
> During the meeting Brian Swetland and Tim Bird were talking about upstreaming
> Android's logger kernel changes. Brian mentioned that logger was in the kernel
> for “performance reasons”. Then later Zach Pfeffer asked if Google had a test
> suite for binder. They said they didn't have anything like that, which I thought
> was really surprising. From that I assume there is no test suite for logger and
> I doubt they have any performance analysis either.
> 
> 	Since logger has a relatively simple interface I felt it would be a good
> target for performance analysis (compared to something like binder). After
> analyzing logger for a little while I decided it would be relatively easy to
> create something similar with shared memory.
> 
> 	The test case that I created uses a POSIX shared memory area as the
> storage medium. This area is different than normal shared memory in that it's
> visible as a file under /dev/shm/ . The shared memory area is protected with a
> System V semaphore. The semaphore is really overkill since contention isn't very
> likely in a real Android logging case. The writers are expected to manage the
> shared area when doing writes. This allows the logging to be daemon-less.
> 
> 	I tried to make the test as much apples to apples as possible. It is somewhat 
> difficult since logger is doing a fair amount of stuff in kernel space which may not
> be needed in userspace, or is difficult to replicate. The read side is typically used 
> infrequently and I don't think performance really matters in that case. I only really 
> address the write side, however my test case includes readers for both (not fully
> tested).
> 
> The test case was run on both x86 and ARM. Results below all in Bytes per second,
> 
> x86:
> +-----------------+----------------------+-------------------+ 
> |Clocksource      |         TSC          |       ACPI_PM     |
> +-----------------+----------------------+-------------------+
> |Shared Memory    |     457172567.4B/s   |     28708407.6B/s |
> +-----------------+----------------------+-------------------+
> |Android Logger   |      77531671.5B/s   |     79575677.3B/s |
> +-----------------+----------------------+-------------------+ 
> 
> ARM:
> +-----------------+----------------------+
> |Shared Memory    |    15336338.6B/s     |
> +-----------------+----------------------+
> |Android Logger   |     6615796.3B/s     |
> +-----------------+----------------------+
> 
> 	The x86 machine was a single core AMD 1.8Ghz machine, and the ARM was a G1
> phone with an MSM7201a SoC using a v3.3 kernel in all cases. I also used chrt to
> elevate the priority of the test case above all other processes in the system. The
> test case was run three time and averaged. The source for the test case is below.
> 
> Noticeably absent is an hpet test. I didn't have one available.
> 
> Conclusions,
> 
> 	The speed of logger isn't really dependent on the clocksource. There
> is very little change between the two clocksource runs on x86 for logger. It's because
> the bottle neck for logger isn't getting the time. The shared memory version does
> depend heavily on the speed of the clocksource. Shared memory with an ACPI_PM
> clocksource is about %64 slower than logger. In the TSC case the shared memory version
> is about %490 faster. The TSC is fast, but using VDSO it's even better.
> 
> 	On ARM it's more straight forward with the Shared Memory version being about
> %132 faster than logger.
> 
> 	As you can see there are some trade offs on x86. I should note that there are
> Android phones being made with x86 platforms. So this isn't as ridiculous as it might
> seem. I would guess most of those phones don't have ACPI_PM clocks however.
> 
> 	I made no attempt to address any security issues in logger. Since logger has
> no security built into it currently. There are at least two ways to provide security
> to the shared memory interface that I know of, but I'm not planning to discuss them in
> this analysis.
> 
> I welcome comments on the test case, or my analysis.
>  
> Here's the test case used,
> 
> 
> /*
>  * Copyright (c) 2012, Daniel Walker <dwalker@fifo99.com>
>  *
>  * gcc -O2 logger_test.c -lrt -lpthread -o logger_test
>  *
>  */
> #include <stdio.h>
> #include <unistd.h>
> #include <stdlib.h>
> #include <string.h>
> #include <signal.h>
> 
> #include <fcntl.h>
> #include <time.h>
> #include <pthread.h>
> #include <errno.h>
> 
> #include <stdint.h>
> #include <semaphore.h>
> #include <sys/mman.h>
> #include <sys/types.h>
> #include <sys/time.h>
> #include <sys/stat.h>
> #include <sys/uio.h>
> 
> char buffer[1024] = { [0 ... 1023] = '0' };
> 
> struct timeval tv1, tv2;
> 
> struct memory_control_area {
> 	sem_t mutex;
> 	unsigned long start, end, size, readers;
> 	_Bool overwrite;
> 	char data[0];
> };
> 
> _Bool stopped = 0;
> 
> #define READ_WAIT_FIFO_NAME	"/tmp/shared_memory_reader_fifo"
> int read_wait_fifo;
> 
> void alarm_handler(int signal)
> {
> 	stopped = 1;
> }
> 
> struct sigaction alarm_overload = {
> 	.sa_handler = alarm_handler,
> };
> 
> void int_handler(int signal)
> {
> 	stopped = 1;
> }
> 
> struct sigaction int_overload = {
> 	.sa_handler = int_handler,
> };
> 
> /*
>  *  This is for compatibility with Android logger
>  */
> #define CONTENT_LINES (64)
> 
> /*
>  *  Size of the memory area. This is minus the control structure.
>  */
> #define CONTENT_SIZE (CONTENT_LINES*1024 - sizeof(struct memory_control_area))
> 
> /*
>  * Subtracts tv1 from tv2 and prints the output.
>  */
> void print_diff_time(char header[], struct timeval *tv1, struct timeval *tv2, unsigned long long bytes)
> {
> 	unsigned long long diff_useconds, diff_seconds;
> 	double total_time;
> 
> 	diff_useconds = (tv2->tv_usec + (tv2->tv_sec*1000000)) -
> 			(tv1->tv_usec + (tv1->tv_sec*1000000)),
> 
> 	total_time = diff_useconds/1000000.0;
> 
> 	printf("%s wrote %llu bytes in %.1f seconds at a rate of %.1f Bytes/second\n",
> 		header, bytes, total_time, (double)(bytes/total_time));
> }
> 
> char *sample_log_string(void)
> {
> 	/*
> 	 *  Just some sample logs for effect.
> 	 */
> 	static char *sample_msgs[16] = {
> 		"New MMC card '00000' (serial 2029453699) added @ /devices/platform/msm_sdcc.2/mmc_host/mmc1/mmc1:0001\n",
> 		"Disk (blkdev 179:0), 7954432 secs (3884 MB) 1 partitions\n",
> 		"New blkdev 179.0 on media 00000, media path /devices/platform/msm_sdcc.2/mmc_host/mmc1/mmc1:0001, Dpp 1\n",
> 		"Partition (blkdev 179:1), 7946240 secs (3880 MB) type 0xb\n",
> 		"New blkdev 179.1 on media 00000, media path /devices/platform/msm_sdcc.2/mmc_host/mmc1/mmc1:0001, Dpp 0\n",
> 		"Evaluating dev '/devices/platform/msm_sdcc.2/mmc_host/mmc1/mmc1:0001/block/mmcblk0' for mountable filesystems for '/sdcard'\n",
> 		"handle_switch_event(): Ignoring switch 'No Device'\n",
> 		"Bootstrapping complete\n",
> 		"dosfsck 3.0.1 (23 Nov 2008)\n",
> 		"akmd 1.6.4 START \n",
> 		"library version: 1.2.1.1129\n",
> 		"dosfsck 3.0.1, 23 Nov 2008, FAT32, LFN\n",
> 		"Logical sector size is zero.\n",
> 		"/system/bin/dosfsck terminated by exit(8)\n",
> 		"Filesystem check failed (not a FAT filesystem)\n",
> 		"vfat filesystem check failed on 179:1 (No data available)\n",
> 	};
> 
> 	static index = 0;
> 	
> 	if (index >= 16) {
> 		index = 0;
> 	}
> 
> 	return sample_msgs[index++];
> }
> 
> void register_signal_handler(int sig, struct sigaction *overload)
> {
> 	int ret = sigaction(sig, overload, NULL);
> 	if (ret < 0) {
> 		perror("sigaction():");
> 		exit(1);
> 	}
> 
> }
> 
> enum fifo_direction {
> 	FIFO_READ,
> 	FIFO_WRITE,
> };
> 
> int open_fifo(enum fifo_direction dir)
> {
> 	int ret = open(READ_WAIT_FIFO_NAME, (dir == FIFO_READ) ? O_RDONLY : O_WRONLY);
> 	if (ret < 0) {
> 		perror("open():");
> 		exit(1);
> 	}
> 	
> }
> 
> /*
>  *  Test this kernels logger interface in /dev/log/
>  */
> void test_logger(int seconds)
> {
> 	int fd, i, ret, prio = 4;
> 	unsigned long long bytes_written = 0;
> 	const char *tag = "";
> 	unsigned long long j;
>     	struct iovec vec[3];
> 
> 	gettimeofday(&tv1, NULL);
> 
> 	fd = open("/dev/log_main", O_WRONLY);
> 	if (fd < 0) {
> 		perror("open():");
> 		exit(1);
> 	}
> 	
> 	stopped = 0;
> 
> 	alarm(seconds);
> 
> 	vec[0].iov_base	= (unsigned char *) &prio;
> 	vec[0].iov_len	= 1;
> 	vec[1].iov_base	= (void *) tag;
> 	vec[1].iov_len	= 1;
> 
> 	while (!stopped) {
> 		char *buffer = sample_log_string();
> 
> 		vec[2].iov_base	= (void *) buffer;
> 		vec[2].iov_len	= strlen(buffer); /* Don't include the null */
> 
> 		ret = writev(fd, vec, 3);
> 		if (ret < 0) {
> 			perror("writev():");
> 			exit(1);
> 		}
> 		bytes_written += ret;
> 	}
> 
> 	close(fd);
> 
> 	gettimeofday(&tv2, NULL);
> 
> 	print_diff_time("Android logger", &tv1, &tv2, bytes_written);	
> }
> 
> void logger_reader()
> {
> 	char buffer[1024];
> 	struct logger_entry {
> 	    uint16_t    len;    /*  length of the payload */
> 	    uint16_t    __pad;  /*  no matter what, we get 2 bytes of padding */
> 	    int32_t     pid;    /*  generating process's pid */
> 	    int32_t     tid;    /*  generating process's tid */
> 	    int32_t     sec;    /*  seconds since Epoch */
> 	    int32_t     nsec;   /*  nanoseconds */
> 	    char        msg[0]; /*  the entry's payload */
> 	} *casted_buffer = (struct logger_entry *)buffer;
> 
> 	int i, size, fd, prio = 0;
> 	struct iovec vec[3]; 
> 	const char *tag = "";
> 
> 	vec[0].iov_base = (void *) buffer,
> 	vec[0].iov_len = 1024,
> 
> 	fd = open("/dev/log_main", O_RDONLY);
> 	if (fd < 0) {
> 		perror("open():");
> 		exit(1);
> 	}
> 
> 	while (size = readv(fd, vec, 1)) { 
> 		for(i = 1; i < casted_buffer->len; i++) {
> 			printf("%c", casted_buffer->msg[i]);
> 		}
> 	}
> 	close(fd);	
> }
> 
> /*
>  *  Test write into shared memory
>  */
> void test_shared_memory(int seconds)
> {
> 	struct memory_control_area *shared_area;
> 	unsigned long long bytes_written = 0;
> 	int fd, i, ret;
> 
> 	stopped = 0;
> 
> 	if (seconds == 0) {
> 		register_signal_handler(SIGINT, &int_overload);
> 	} else {
> 		alarm(seconds);
> 	}
> 
> 	gettimeofday(&tv1, NULL);
> 
> 	fd = shm_open("/shared_memory_test", O_CREAT | O_RDWR, S_IRUSR | S_IRGRP | S_IWUSR | S_IWGRP);
> 	if (fd < 0) {
> 		perror("shm_open():");
> 		exit(1);
> 	}
> 
> 	ret = ftruncate(fd, CONTENT_SIZE);
> 	if (ret < 0) {
> 		perror("ftruncate():");
> 		exit(1);
> 	}
> 
> 	shared_area = (struct memory_control_area *)mmap(NULL, CONTENT_SIZE, PROT_READ | PROT_WRITE, MAP_SHARED | MAP_LOCKED, fd, 0);
> 	if (shared_area == MAP_FAILED) {
> 		perror("mmap():");
> 		exit(1);
> 	}
> 
> 	while (!stopped) {
> 		char *buffer = sample_log_string();
> 		int buffer_size = strlen(buffer); /* don't write the null */
> 		struct timeval sample;
> 
> 		sem_wait(&shared_area->mutex);
> 		
> 		/*
> 		 *  This isn't used but it's here for compatibility with
> 		 *  logger. Since logger samples the time on each write.
> 		 *  This can also be a delay sink depending on which clocksource
> 		 *  your using.
> 		 */
> 		gettimeofday(&sample, NULL);
> 
> 		/*
> 		 *  Two cases. The first one handles when the buffer loops
> 		 *  around to the start, the second is just a regular write.
> 		 */
> 		if(shared_area->end + buffer_size >= CONTENT_SIZE)
> 		{
> 			unsigned long rem = CONTENT_SIZE - shared_area->end;
> 	
> 			memcpy(shared_area->data + shared_area->end, buffer, rem);
> 
> 			/* Loop around to the start of the buffer */
> 			shared_area->end = 0;
> 
> 			memcpy(shared_area->data + shared_area->end, buffer + rem, buffer_size - rem);
> 			
> 			shared_area->end = buffer_size - rem;
> 
> 			shared_area->overwrite = 1;
> 
> 		} else {
> 			memcpy(shared_area->data + shared_area->end, buffer, buffer_size);
> 			shared_area->end += buffer_size;
> 		}
> 
> 		if (shared_area->overwrite)
> 			shared_area->start = shared_area->end + 1;
> 
> 		sem_post(&shared_area->mutex);
> 
> 		bytes_written += buffer_size; 
> 	}
> 
> 	close(fd);
> 
> 	gettimeofday(&tv2, NULL);
> 
> 	print_diff_time("Shared memory", &tv1, &tv2, bytes_written);	
> 
> }
> 
> void init_shared_memory_file(void)
> {
> 	struct memory_control_area *shared_area;
> 	int fd, ret, i;
> 
> 	fd = shm_open("/shared_memory_test", O_CREAT | O_RDWR, S_IRUSR | S_IRGRP | S_IWUSR | S_IWGRP);
> 	if (fd < 0) {
> 		perror("shm_open():");
> 		exit(1);
> 	}
> 
> 	ret = ftruncate(fd, CONTENT_SIZE);
> 	if (ret < 0) {
> 		perror("ftruncate():");
> 		exit(1);
> 	}
> 
> 	shared_area = (struct memory_control_area *)mmap(NULL, CONTENT_SIZE, PROT_READ | PROT_WRITE, MAP_SHARED | MAP_LOCKED, fd, 0);
> 	if (shared_area == MAP_FAILED) {
> 		perror("mmap():");
> 		exit(1);
> 	}
> 
> 	/* Warm up the shared memory area */
> 	for (i = 0; i < CONTENT_SIZE - sizeof(struct memory_control_area); i++)
> 		shared_area->data[i] = 0;
> 
> 	sem_init(&shared_area->mutex, 1, 1);
> 
> 	shared_area->readers = 0;
> 	shared_area->start = 0;
> 	shared_area->end = 0;
> 
> 	close(fd);
> }
> 
> void shared_memory_reader()
> {
> 	int fd, i, ret, bytes_to_read, bytes_read = 0;
> 	struct memory_control_area *shared_area;
> 	char output_buf[1024];
> 
> 	fd = shm_open("/shared_memory_test", O_CREAT | O_RDWR, S_IRUSR | S_IRGRP | S_IWUSR | S_IWGRP);
> 	if (fd < 0) {
> 		perror("shm_open():");
> 		exit(1);
> 	}
> 
> 	ret = ftruncate(fd, CONTENT_SIZE);
> 	if (ret < 0) {
> 		perror("ftruncate():");
> 		exit(1);
> 	}
> 
> 	shared_area = (struct memory_control_area *)mmap(NULL, CONTENT_SIZE, PROT_READ | PROT_WRITE, MAP_SHARED | MAP_LOCKED, fd, 0);
> 	if (shared_area == MAP_FAILED) {
> 		perror("mmap():");
> 		exit(1);
> 	}
> 	
> 	bytes_to_read = CONTENT_SIZE - shared_area->end;
> 
> 	while (bytes_to_read) {
> 		if (bytes_to_read >= 1024) {
> 			memcpy(output_buf, shared_area->data + shared_area->end + bytes_read, 1024);
> 			bytes_read += 1024;
> 			bytes_to_read -= 1024;
> 		} else {
> 			memcpy(output_buf, shared_area->data + shared_area->end + bytes_read, bytes_to_read);
> 			bytes_read += bytes_to_read;
> 			bytes_to_read = 0;
> 		}
> 		
> 		for(i = 0; i < 1024; i++)
> 			printf("%c", output_buf[i]);	
> 	}
> 	
> 	bytes_to_read = shared_area->end;
> 
> 	while (bytes_to_read) {
> 		if (bytes_to_read >= 1024) {
> 			memcpy(output_buf, shared_area->data + bytes_read, 1024);
> 			bytes_read += 1024;
> 			bytes_to_read -= 1024;
> 		} else {
> 			memcpy(output_buf, shared_area->data + bytes_read, bytes_to_read);
> 			bytes_read += bytes_to_read;
> 			bytes_to_read = 0;
> 		}
> 
> 		for(i = 0; i < 1024; i++)
> 			printf("%c", output_buf[i]);
> 	}
> }
> 
> int main(int argc, char *argv[])
> {
> 	char help[] =	"Android Logger Performance Tester\n"
> 			"\n"
> 			"Options:\n"
> 			"-l:	Test android logger in /dev/log/ (default)\n"
> 			"-s:	Test shared memory in /dev/shm\n"
> 			"	Must be mount with a command similar to \"mount -t tmpfs none /dev/shm\"\n"
> 			"-n X:	Number of seconds to run the test (default 60, 0 == unlimited)\n"
> 			"-i:	Initialize shared memory file\n"
> 			"-r:	Run shared memory reader\n"
> 			"-t:	Run logger reader\n"
> 			"\n";			
> 
> 	int c, ret;
> 	int seconds = 60;
> 
> 	ret = mlockall(MCL_CURRENT | MCL_FUTURE);
> 	if (ret < 0) {
> 		perror("mlockall():");
> 		exit(1);
> 	}
> 
> 	register_signal_handler(SIGALRM, &alarm_overload);
> 
> 	if (access(READ_WAIT_FIFO_NAME, F_OK) < 0) {
> 		ret = mkfifo(READ_WAIT_FIFO_NAME, S_IWUSR | S_IWGRP | S_IRUSR | S_IRGRP);
> 		if (ret < 0) {
> 			perror("mkfifo():");
> 			exit(1);
> 		}
> 	}
> 
> 	while ((c = getopt(argc, argv, "hiutlsrn:")) != -1)  {
> 
> 		switch (c) {
> 			case 'h':
> 				printf("%s\n", help);
> 				break;	
> 			case 'u':
> 				if (shm_unlink("/shared_memory_test") != 0) {
> 					perror("shm_unlink():");
> 					exit(1);
> 				}
> 			case 'i':
> 				init_shared_memory_file();
> 				break;
> 			case 'l':
> 				test_logger(seconds);
> 				break;
> 			case 's':
> 				test_shared_memory(seconds);
> 				break;
> 			case 'r':
> 				shared_memory_reader();
> 				break;
> 			case 't':
> 				logger_reader();
> 				break;
> 			case 'n':
> 				errno = 0;
> 				seconds = strtoll(optarg, NULL, 10);
> 				if (errno != 0) {
> 					perror("strtol():");
> 					exit(1);
> 				}
> 		}
> 	}
> 
> 	return 0;
> }
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
> 

Re: [RFC] Android Logger vs. Shared Memory FIGHT!

[Tim Bird]

On 03/29/2012 07:50 AM, Daniel Walker wrote:
> On Wed, Mar 28, 2012 at 02:06:32PM -0700, Daniel Walker wrote:
>>
>>
>>       I went to Linaro Connect a few weeks ago. While I was there they held a
>> meeting with some of the Android developers and some community developers.
>> During the meeting Brian Swetland and Tim Bird were talking about upstreaming
>> Android's logger kernel changes. Brian mentioned that logger was in the kernel
>> for “performance reasons”. 

...
>         I made no attempt to address any security issues in logger. Since logger has
> no security built into it currently. There are at least two ways to provide security
> to the shared memory interface that I know of, but I'm not planning to discuss them in
> this analysis.

At the mainlining meeting at Connect, we discussed some of the security and
robustness issues with logger, that would affect whether a user-space-only
solution would work.

See the etherpad at:
http://summit.linaro.org/lcq1-12/meeting/20039/linaro-kernel-q112-android-mainlining-f2f-2/

There is concern about applications leaking sensitive data into the logs,
and a desire to possibly (in the future) support per-application logs
for some apps.  Having the code in-kernel means that things like the
timestamp, tid and pid cannot be forged by the process.  The separation
into channels and kernel management of the read/write position provide
an impediment to denial of service attacks.

At the moment, I'm not considering an alternative for logger that runs
completely in user-space.  Having said that, this test is certainly interesting,
and may provide some performance numbers for logger or alternatives that would
be useful to compare.

I like that you've put the gettimeofday() into the shared memory test, to
capture the cost of the timestamp operation.  Presumably, the fact that
x86 has VDSO and ARM does not is contributing to the performance difference
between the two platforms.

I'm a little worried about caching effects for this test, since it
seems like it would run in a very tight loop (with the
exception of the gettimeofday() or the call to logger.


> x86:
> +-----------------+----------------------+-------------------+
> |Clocksource      |         TSC          |       ACPI_PM     |
> +-----------------+----------------------+-------------------+
> |Shared Memory    |     457172567.4B/s   |     28708407.6B/s |
> +-----------------+----------------------+-------------------+
> |Android Logger   |      77531671.5B/s   |     79575677.3B/s |
> +-----------------+----------------------+-------------------+
>
> ARM:
> +-----------------+----------------------+
> |Shared Memory    |    15336338.6B/s     |
> +-----------------+----------------------+
> |Android Logger   |     6615796.3B/s     |
> +-----------------+----------------------+

Tests were 60 seconds.  I presume there were multiple runs and these are
averages.  Can you provide the number of runs and the standard deviation for
each set?

Thanks,
 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Workgroup of the Linux Foundation
Senior Staff Engineer, Sony Network Entertainment
=============================

Re: [RFC] Android Logger vs. Shared Memory FIGHT!

[Daniel Walker]

On Thu, Mar 29, 2012 at 09:25:26AM -0700, Tim Bird wrote:
> 
> There is concern about applications leaking sensitive data into the logs,
> and a desire to possibly (in the future) support per-application logs
> for some apps.  Having the code in-kernel means that things like the
> timestamp, tid and pid cannot be forged by the process.  The separation
> into channels and kernel management of the read/write position provide
> an impediment to denial of service attacks.

it's unclear what problem would be caused by forging a PID, and why any
app would want to do that. It doesn't look like it would cause any
problems.

> At the moment, I'm not considering an alternative for logger that runs
> completely in user-space.  Having said that, this test is certainly interesting,
> and may provide some performance numbers for logger or alternatives that would
> be useful to compare.

It's certainly up to you what you want to use, but I don't see why any
other architecture or OS would want to use logger.
 
> I like that you've put the gettimeofday() into the shared memory test, to
> capture the cost of the timestamp operation.  Presumably, the fact that
> x86 has VDSO and ARM does not is contributing to the performance difference
> between the two platforms.

John Stultz commented on how gettimeofday() is more accurate that what
is needed. Logger actually uses a less accurate, and faster, method of timing.
The time isn't exactly apples to apples, my shared memory example is actually
using a slower clock compared to logger.
 
> 
> Tests were 60 seconds.  I presume there were multiple runs and these are
> averages.  Can you provide the number of runs and the standard deviation for
> each set?


Test cases were 600 seconds (10 minutes) .. There were three runs. 
Here's the raw data, all in bytes per second:

X86:
Logger TSC = 70072480.0, 83911562.7, 78610971.8
Shared Memory TSC = 460262336.0, 454204684.1, 457050682.2

Logger ACPI_PM = 75523320.0, 81615111.9, 81588600.2
Shared Memory ACPI_PM = 29688532.0, 28211029.2, 28225661.6


ARM:
Logger = 6985508.0, 5827587.3, 7034293.7
Shared Memory = 12371886.7, 18362639.9, 15274489.3

You can feel free to compute the standard deviation if you wish.

Daniel

Re: [RFC] Android Logger vs. Shared Memory FIGHT!

[Tim Bird]

On 03/29/2012 10:09 AM, Daniel Walker wrote:
> John Stultz commented on how gettimeofday() is more accurate that what
> is needed. Logger actually uses a less accurate, and faster, method of timing.
> The time isn't exactly apples to apples, my shared memory example is actually
> using a slower clock compared to logger.

OK - that's interesting.
>  
>>
>> Tests were 60 seconds.  I presume there were multiple runs and these are
>> averages.  Can you provide the number of runs and the standard deviation for
>> each set?
> 
> 
> Test cases were 600 seconds (10 minutes) .. There were three runs. 
> Here's the raw data, all in bytes per second:
> 
> X86:
> Logger TSC = 70072480.0, 83911562.7, 78610971.8
> Shared Memory TSC = 460262336.0, 454204684.1, 457050682.2
> 
> Logger ACPI_PM = 75523320.0, 81615111.9, 81588600.2
> Shared Memory ACPI_PM = 29688532.0, 28211029.2, 28225661.6
> 
> 
> ARM:
> Logger = 6985508.0, 5827587.3, 7034293.7
> Shared Memory = 12371886.7, 18362639.9, 15274489.3


> You can feel free to compute the standard deviation if you wish.

Here are the std deviations:

x86-logger-tsc: 7.4%
x86-shmem-tsc: 0.5%
x86-logger-ACPI_PM: 3.6%
x86-shmem-ACPI_PM: 2.4%
ARM-logger: 8.4%
ARM-shmem: 15.9%

Performance ratios:
x86-shmem-tsc/x86-logger-tsc -> 5.9
x86-shmem-ACPI_PM/x86-logger-ACPI_PM -> 0.36
ARM-shem/ARM-logger -> 2.3

It would be nice to understand why the ARM numbers are
not more consistent.  I'll try to take a look at this next week.

Thanks for the data.

I recently started work on my own performance test suite
for logger.  I'm taking the approach of simulating log
insertions based on log timings from a sampled device, and
measuring cost per message.  I'm not sure when I'll finish
it, but I'll post results when I have them.
  -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Workgroup of the Linux Foundation
Senior Staff Engineer, Sony Network Entertainment
=============================

Re: [RFC] Android Logger vs. Shared Memory FIGHT!

[Daniel Walker]

On Thu, Mar 29, 2012 at 09:25:26AM -0700, Tim Bird wrote:
> At the moment, I'm not considering an alternative for logger that runs
> completely in user-space.  Having said that, this test is certainly interesting,
> and may provide some performance numbers for logger or alternatives that would
> be useful to compare.


I was just thinking what does an accurate PID actually get you? If you
looking at some logs with a PID of 20048, does that mean something to
you? It doesn't actually mean much because you can't map that back to
anything. If you have the device, and the process is still running then
you could look it up ..

So lets say logger was modified to record comm values.. That way you
could record the actual process name AND the pid. Well if you use
prctl(PR_SET_NAME), you can forge comm values. So that doesn't get you
much either..

So even if you record accurate PID values, it doesn't mean anything
anyway.

Daniel

Re: [RFC] Android Logger vs. Shared Memory FIGHT!

[Tim Bird]

On 3/29/2012 10:52 AM, Daniel Walker wrote:
> On Thu, Mar 29, 2012 at 09:25:26AM -0700, Tim Bird wrote:
>> At the moment, I'm not considering an alternative for logger that runs
>> completely in user-space.  Having said that, this test is certainly interesting,
>> and may provide some performance numbers for logger or alternatives that would
>> be useful to compare.
>
> I was just thinking what does an accurate PID actually get you? If you
> looking at some logs with a PID of 20048, does that mean something to
> you? It doesn't actually mean much because you can't map that back to
> anything. If you have the device, and the process is still running then
> you could look it up ..
>
> So lets say logger was modified to record comm values.. That way you
> could record the actual process name AND the pid. Well if you use
> prctl(PR_SET_NAME), you can forge comm values. So that doesn't get you
> much either..
>
> So even if you record accurate PID values, it doesn't mean anything
> anyway.
Putting bogus pids in the log would allow a log DDOS-er to hide their
activity more easily.  But with the log in user-space, there are much more
insidious things that could be done to hide or corrupt log activity.  So
the sensitivity of this particular piece of log data is not that great.
  -- Tim

Re: [RFC] Android Logger vs. Shared Memory FIGHT!

[Daniel Walker]

On Thu, Mar 29, 2012 at 11:20:17AM -0700, Tim Bird wrote:
> Putting bogus pids in the log would allow a log DDOS-er to hide their
> activity more easily.  But with the log in user-space, there are much more
> insidious things that could be done to hide or corrupt log activity.  So
> the sensitivity of this particular piece of log data is not that great.
>  -- Tim


	Bogus pids or real pids it doesn't matter you can't map the pid
back to the process.

	It's true that you can wipe the whole shared memory area if it's
in userspace, but there are ways to handle that .. Not to mention
motivation due to a massive speed up over logger. For instance each app
could log to it's own logging area, and the permissions wouldn't allow
any other app to write into that area..

	You know a DoS process could just not log anything .. There's far too
many other ways to kill the system..

Daniel

Re: [RFC] Android Logger vs. Shared Memory FIGHT!

[Alan Cox]

On Thu, 29 Mar 2012 10:52:10 -0700
Daniel Walker <dwalker@fifo99.com> wrote:

> On Thu, Mar 29, 2012 at 09:25:26AM -0700, Tim Bird wrote:
> > At the moment, I'm not considering an alternative for logger that runs
> > completely in user-space.  Having said that, this test is certainly interesting,
> > and may provide some performance numbers for logger or alternatives that would
> > be useful to compare.
> 
> 
> I was just thinking what does an accurate PID actually get you? If you
> looking at some logs with a PID of 20048, does that mean something to
> you? It doesn't actually mean much because you can't map that back to
> anything. If you have the device, and the process is still running then
> you could look it up ..
> 
> So lets say logger was modified to record comm values.. That way you
> could record the actual process name AND the pid. Well if you use
> prctl(PR_SET_NAME), you can forge comm values. So that doesn't get you
> much either..
> 
> So even if you record accurate PID values, it doesn't mean anything
> anyway.

The question is whether you are trying to record data for analysis in a
hostile environment or you are trying to do useful debugging. If your
apps are non hostile then PR_SET_NAME is actually useful in logging to
split apart different executions of the same daemon.

The Android logger has no security model of any real kind so it's clearly
about the debug side. In that case the PID lets you correlate with other
logs, the comm data might be useful.

Alan

Re: [RFC] Android Logger vs. Shared Memory FIGHT!

[Daniel Walker]

On Thu, Mar 29, 2012 at 07:50:07PM +0100, Alan Cox wrote:
> 
> The question is whether you are trying to record data for analysis in a
> hostile environment or you are trying to do useful debugging. If your
> apps are non hostile then PR_SET_NAME is actually useful in logging to
> split apart different executions of the same daemon.

True..
 
> The Android logger has no security model of any real kind so it's clearly
> about the debug side. In that case the PID lets you correlate with other
> logs, the comm data might be useful.

	Your right it doesn't have much in terms of security, but Tim is suggesting
that it is a hostile environment in need of what little security it has.

	If your logging on a hostile system then Android's logger and my shared
memory version are both wide open. However, that doesn't mean you could lock
both down in some way.

Daniel

Re: [RFC] Android Logger vs. Shared Memory FIGHT!

[Tim Bird]

On 03/29/2012 11:50 AM, Alan Cox wrote:
> The question is whether you are trying to record data for analysis in a
> hostile environment or you are trying to do useful debugging. If your
> apps are non hostile then PR_SET_NAME is actually useful in logging to
> split apart different executions of the same daemon.
> 
> The Android logger has no security model of any real kind so it's clearly
> about the debug side. In that case the PID lets you correlate with other
> logs, the comm data might be useful.

The current model has limited security, other than being in the kernel
and thus harder to corrupt (but still subject to DOS attacks
via overruning the log).

I think the envisioned security issues are more about preventing
access to application logs which might reveal sensitive information
(due to un-careful logging), than about analysing a hostile
environment.  But if it can be made harder for a bad program to
cover it's tracks, that would be nice.
 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Workgroup of the Linux Foundation
Senior Staff Engineer, Sony Network Entertainment
=============================

Re: [RFC] Android Logger vs. Shared Memory FIGHT!

[Daniel Walker]

On Thu, Mar 29, 2012 at 03:19:08PM -0700, Tim Bird wrote:
> environment.  But if it can be made harder for a bad program to
> cover it's tracks, that would be nice.

Do you think adding this extra level of security is worth adding a new
kernel interface for logging ?

Daniel