lkml.org 
[lkml]   [2012]   [Mar]   [29]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [RFC] Android Logger vs. Shared Memory FIGHT!
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/
>
--
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/

\
 
 \ /
  Last update: 2012-03-29 16:53    [W:0.079 / U:0.048 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site