At very high diagchar logging rates (a HSPA+ ftp download with many instantaneous diag log response messages enabled) on quad-core phones, it was observed that after about 2 to 20 minutes (depends on logging rate) - the userspace read to /dev/diag would block, causing a freeze effect to the userspace program - and further attempts to log would randomly freeze at an earlier stage then a phone restart was required to do any meaningful logging. You can test this with "diag_mdlog", use a diag.cfg with high logging rate log_response_messages like 0x4222, 0x4179 and other fast logs.
The patched kernel was tested on a "Google Nexus 4 with Android 4.2.2" (mako) phone - and had no more freezes even after 13 Hours of logging diag for over-night ftp tests, an older sister-kernel (essentially the same - but with many more pr_debug() to identify the causes) was also tested sucessfully on two other "Google Nexus 4" phones, one of them logged successfully through about 10 hours of fast ftp downloads - no freezes too. This fix consists of 4 main parts: 1. There were cases that diag_device_write() completed the "enque" and sets the data_ready flag during an ongoing diagchar_read() which would then clear the flag on completion - resulting in a lost data_ready notification and diagchar_read() would block by waiting for the lost wakeup. The extra flag (array) "data_ready_while_busy" was introduced to handle that situation. 2. It was observed that zero length buffers in diag_hsic_read_complete_callback() was causing problems too - sending zero length entries to the hsic_buf_tbl queue could cause it to never be properly dequeued and never "diagmem_free()". This is because diagfwd.c's diag_device_write() would successfully "enqueue" it but then diagchar_core.c's diagchar_read() would omit it because "if (driver->hsic_buf_tbl[i].length > 0)". So it won't be "dequeued" and also diagmem_free would not be called on it. This is fixed by not allowing zero-length entries into diag_device_write() - and then calling diagmem_free() on it instead. 3. Consecutive writes (try 10+ conf writes before reading) to diagchar from userspace would block, although normal steps and ioctl were done. This was because the diagchar_write() was blocked in wait_event_interruptible() but the diag_hsic_write_complete_callback() didn't wake it up. I simply added a wake_up_interruptible() in that callback and now the consecutive writes complete sucessfully. 4. At very high logging rates (on the Nexus 4 quad-core phone), it was observed that "count_hsic_write_pool" faced read/write race conditions (to increment and decrement) and became incorrect - even negative - and "diag_read_hsic_work_fn" would use it to "determine the current number of available buffers for writing after reading from the HSIC has completed" - so the code was modified to determine the number of entries available by iterating through "hsic_buf_tbl" instead. Also, added a "driver->num_clients--" to diagchar_close() to update num_clints on close() from userspace. Signed-off-by: Kasidit Yusuf <[email protected]> --- drivers/char/diag/diagchar.h | 1 + drivers/char/diag/diagchar_core.c | 21 ++++++++++- drivers/char/diag/diagfwd.c | 16 ++++++++ drivers/char/diag/diagfwd_hsic.c | 79 ++++++++++++++++++++++++++++++++------- 4 files changed, 103 insertions(+), 14 deletions(-) diff --git a/drivers/char/diag/diagchar.h b/drivers/char/diag/diagchar.h index 8d87cf9..4281912 100644 --- a/drivers/char/diag/diagchar.h +++ b/drivers/char/diag/diagchar.h @@ -142,6 +142,7 @@ struct diagchar_dev { wait_queue_head_t wait_q; struct diag_client_map *client_map; int *data_ready; + int *data_ready_while_busy; int num_clients; int polling_reg_flag; struct diag_write_device *buf_tbl; diff --git a/drivers/char/diag/diagchar_core.c b/drivers/char/diag/diagchar_core.c index 2c572ed..9132fcb 100644 --- a/drivers/char/diag/diagchar_core.c +++ b/drivers/char/diag/diagchar_core.c @@ -182,6 +182,13 @@ static int diagchar_open(struct inode *inode, struct file *file) goto fail; else driver->data_ready = temp; + temp = krealloc(driver->data_ready_while_busy + , (driver->num_clients) * sizeof(int), + GFP_KERNEL); + if (!temp) + goto fail; + else + driver->data_ready_while_busy = temp; diag_add_client(i, file); } else { mutex_unlock(&driver->diagchar_mutex); @@ -221,6 +228,8 @@ static int diagchar_close(struct inode *inode, struct file *file) struct diagchar_priv *diagpriv_data = file->private_data; pr_debug("diag: process exit %s\n", current->comm); + driver->num_clients--; + if (!(file->private_data)) { pr_alert("diag: Invalid file pointer"); return -ENOMEM; @@ -804,6 +813,7 @@ static int diagchar_read(struct file *file, char __user *buf, size_t count, wait_event_interruptible(driver->wait_q, driver->data_ready[index]); + driver->data_ready_while_busy[index] = 0; mutex_lock(&driver->diagchar_mutex); if ((driver->data_ready[index] & USER_SPACE_LOG_TYPE) && (driver-> @@ -981,7 +991,16 @@ drop_hsic: /* copy number of data fields */ COPY_USER_SPACE_OR_EXIT(buf+4, num_data, 4); ret -= 4; - driver->data_ready[index] ^= USER_SPACE_LOG_TYPE; + + /* At very high logging rates, it was observed that + * sometimes diag_device_write() completed the "enqueue" + * and sets the data_ready flag during an ongoing read + * in the lines above - so we should not clear the flag + * in these cases + */ + if (driver->data_ready_while_busy[index] == 0) + driver->data_ready[index] ^= USER_SPACE_LOG_TYPE; + if (driver->ch) queue_work(driver->diag_wq, &(driver->diag_read_smd_work)); diff --git a/drivers/char/diag/diagfwd.c b/drivers/char/diag/diagfwd.c index 4419309..7f12a3f 100644 --- a/drivers/char/diag/diagfwd.c +++ b/drivers/char/diag/diagfwd.c @@ -332,6 +332,12 @@ int diag_device_write(void *buf, int proc_num, struct diag_request *write_ptr) driver->logging_process_id) break; if (i < driver->num_clients) { + /* Set a "data_ready_while_busy" flag to + * prevent diagchar_read() from clearing new + * data_ready sets that came during its ongoing read. + */ + driver->data_ready_while_busy[i] |= USER_SPACE_LOG_TYPE; + driver->data_ready[i] |= USER_SPACE_LOG_TYPE; pr_debug("diag: wake up logging process\n"); wake_up_interruptible(&driver->wait_q); @@ -2056,6 +2062,14 @@ void diagfwd_init(void) , GFP_KERNEL)) == NULL) goto err; kmemleak_not_leak(driver->data_ready); + if (driver->data_ready_while_busy == NULL) { + driver->data_ready_while_busy = kzalloc(driver->num_clients + * sizeof(int) + , GFP_KERNEL); + if (driver->data_ready_while_busy == NULL) + goto err; + } + kmemleak_not_leak(driver->data_ready_while_busy); if (driver->table == NULL && (driver->table = kzalloc(diag_max_reg* sizeof(struct diag_master_table), @@ -2166,6 +2180,7 @@ err: kfree(driver->client_map); kfree(driver->buf_tbl); kfree(driver->data_ready); + kfree(driver->data_ready_while_busy); kfree(driver->table); kfree(driver->pkt_buf); kfree(driver->write_ptr_1); @@ -2217,6 +2232,7 @@ void diagfwd_exit(void) kfree(driver->client_map); kfree(driver->buf_tbl); kfree(driver->data_ready); + kfree(driver->data_ready_while_busy); kfree(driver->table); kfree(driver->pkt_buf); kfree(driver->write_ptr_1); diff --git a/drivers/char/diag/diagfwd_hsic.c b/drivers/char/diag/diagfwd_hsic.c index bd8c52b..94d8b9d 100644 --- a/drivers/char/diag/diagfwd_hsic.c +++ b/drivers/char/diag/diagfwd_hsic.c @@ -45,6 +45,7 @@ static void diag_read_hsic_work_fn(struct work_struct *work) int num_reads_submitted = 0; int err = 0; int write_ptrs_available; + int i; if (!driver->hsic_ch) { pr_err("DIAG in %s: driver->hsic_ch == 0\n", __func__); @@ -55,12 +56,30 @@ static void diag_read_hsic_work_fn(struct work_struct *work) * Determine the current number of available buffers for writing after * reading from the HSIC has completed. */ - if (driver->logging_mode == MEMORY_DEVICE_MODE) - write_ptrs_available = driver->poolsize_hsic_write - - driver->num_hsic_buf_tbl_entries; - else + if (driver->logging_mode == MEMORY_DEVICE_MODE) { + /* + * At very high logging rates on multi-core phones, + * it was observed that "count_hsic_write_pool" faced read/write + * race conditions (to increment and decrement) and became + * incorrect - so don't use it to determine the number of + * entries available - iterate through "hsic_buf_tbl" instead. + */ + write_ptrs_available = 0; + i = (driver->poolsize_hsic_write) - 1; + for (; i >= 0; i--) + if (driver->hsic_buf_tbl[i].length == 0) + write_ptrs_available++; + } else { write_ptrs_available = driver->poolsize_hsic_write - driver->count_hsic_write_pool; + } + + if (driver->logging_mode == MEMORY_DEVICE_MODE && + (write_ptrs_available <= 0 || + write_ptrs_available > driver->poolsize_hsic_write)) { + pr_debug("diag: warning - probe write_ptrs_available: %d" + , write_ptrs_available); + } /* * Queue up a read on the HSIC for all available buffers in the @@ -138,17 +157,50 @@ static void diag_hsic_read_complete_callback(void *ctxt, char *buf, if (!buf) { pr_err("diag: Out of diagmem for HSIC\n"); } else { - /* - * Send data in buf to be written on the - * appropriate device, e.g. USB MDM channel + + /* Contradicting with the original comment above to send + * zero length entries, sending 0 length entries to the + * hsic_buf_tbl queue could cause it to never be + * properly dequeued and never "diagmem_free()". + * + * This is because diagfwd.c's diag_device_write() would + * successfully "enqueue" it but then diagchar_core.c's + * diagchar_read() would omit it - + * because "if (driver->hsic_buf_tbl[i].length > 0)"... + * So it won't be "dequeued" and also diagmem_free would + * not be called on it. + * + * Also, other diag_device_write() calls with non-0 + * length entries would also overwrite this 0-length + * entry because of the + * "if (driver->hsic_buf_tbl[i].length == 0)" check. + * + * Threrefore, if the actual_size is > 0, send it, + * but if the size is 0 then call diagmem_free + * on it and don't send it. */ - driver->write_len_mdm = actual_size; - err = diag_device_write((void *)buf, HSIC_DATA, NULL); - /* If an error, return buffer to the pool */ - if (err) { + + if (actual_size > 0) { + /* + * Send data in buf to be written on the + * appropriate device, e.g. USB MDM channel + */ + driver->write_len_mdm = actual_size; + err = diag_device_write((void *)buf, + HSIC_DATA, NULL); + /* If an error, return buffer to the pool */ + if (err) { + diagmem_free(driver, buf, + POOL_TYPE_HSIC); + pr_err("diag: In %s, error calling diag_device_write, err: %d\n", + __func__, err); + } + } else { + /* if we reach here this means actual_size is 0 + * then free and omit it. + */ + err = 0; diagmem_free(driver, buf, POOL_TYPE_HSIC); - pr_err("diag: In %s, error calling diag_device_write, err: %d\n", - __func__, err); } } } else { @@ -179,6 +231,7 @@ static void diag_hsic_write_complete_callback(void *ctxt, char *buf, { /* The write of the data to the HSIC bridge is complete */ driver->in_busy_hsic_write = 0; + wake_up_interruptible(&driver->wait_q); if (!driver->hsic_ch) { pr_err("DIAG in %s: driver->hsic_ch == 0\n", __func__); -- 1.8.1.5 -- To unsubscribe from this list: send the line "unsubscribe linux-arm-msm" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html
