PRS-T1 Enormous battery drain

RhialtoFalu · 07-13-2012, 06:25 AM

First, the context:

About a week ago something weird happened with my T1. It had been rooted with Porkupan's sets. I have never installed any firmware updates so it was still the 1.0.00.09720 version.
I was just turning a page in CoolReader when I got stuck in a reboot loop. A few seconds the rotating arrows, then a blank screen for a few seconds, and repeating.
After a forced reset with a paperclip, the T1 restarted a bit better, but many programs "accidentally terminated": at least BarTab, Keyboard, ADW Launcher... but the original Sony programs seemed to be still working.
I have been reading books in this situation for a day or 2.

Since this appeared to be more or less a software problem (although it was worrying that this started so suddenly) I thought to do a restore and firmware update. I started out with the official Sony firmware update to 1.0.04 updater, but it didn't want to do anything. (No "updating" appeared on the screen and the firmware version wasn't changed).
So, I tried a SD rescue set of Rupor to go to 1.00.04 that way. That also wasn't a 100% success; it was supposed to take 20 minutes but after a few hours I gave up and I reset. It turned out it had reverted to an apparently clean and unrooted version of 1.00.00.
Ok, so I tried the Sony updater again and this time it worked, giving me a clean 1.00.04.
As I understand it, this update replaces ALL firmware, the kernel, ramdisk, the recovery environment and the Android environment, right? So whatever had been corrupted would have been replaced by now.
After that I installed Rupor's AMR and his pack to enable ADB/Apps2SD.
All this seemed to work fine. I re-installed CoolReader.

However, and now we get to the problem:

the battery lasts barely more than overnight now! Even when the reader is in sleep mode, after a few hours more than overnight, it shuts down. The last thing it does is put up a warning screen that the battery has low power, and that it is disabling the network (which wasn't enabled in the first place).

Would this be a software problem (some software that keeps running and eating power), or some hardware problem after all? If I try to get a warranty repair/replacement it would be annoying if it was some software issue which I could have fixed myself.

Looking at the software angle, here are the first few lines from the output of top in the adb shell.
This "pastlog_thread" seems to be running all the time, and 23% system CPU time seems rather high... the reader was supposed to be idle at the time apart from running top and adb over usb.

Code:

User 0%, System 23%, IOW 0%, IRQ 0%
User 2 + Nice 0 + Sys 74 + Idle 234 + IOW 0 + IRQ 0 + SIRQ 0 = 310

  PID CPU% S  #THR     VSS     RSS PCY UID      Name
 1110  13% D     1      0K      0K  fg root     pastlog_thread
  310   8% S     1      0K      0K  fg root     esdhc_wq/0
 2626   3% R     1    948K    388K  fg root     top
 2137   0% S    47 278676K  41256K  fg system   system_server
    5   0% S     1      0K      0K  fg root     khelper
    8   0% S     1      0K      0K  fg root     async/mgr
    9   0% S     1      0K      0K  fg root     pm
   12   0% S     1      0K      0K  fg root     suspend
   76   0% S     1      0K      0K unk root     usb_wakeup thre

Edit: I also tried the battery recalibration by removing the file /data/system/batterystats.bin. It made no difference.

uboot · 07-13-2012, 06:12 PM

what about this one: https://www.mobileread.com/forums/sho...d.php?t=181673

RhialtoFalu · 07-22-2012, 10:31 AM

uboot: thanks for that lead. I have been poking at my T1 for the last week or so, and it seems that the problem has resolved "itself". Or at least, I have some idea of what might have fixed it but I'm not 100% sure about that. (I am still in the dark about how the problem started in the first place).

Here is the narrative (for the benefit of people having similar problems who might now find this through google):

I poked around with BetterBatteryStats (BBS), both while the reader was connected to USB (and charging), and when disconnected. However BBS had a tendency to stop responding as soon as I disconnected the USB cable, so that wasn't terribly useful. Also it managed to write a log file only twice out of many many attempts.

BBS showed active kernel wake locks for pretty much most of the time: past_wake_lock for over 90%... that's what apparently kept the reader awake. As already shown above, there was also a "pastlog_thread" being relatively active. "past_wake_lock" was not known by google!

Only after several days I thought to look at the linux system log (through the dmesg command). It turned out to contain only lines like this:

Code:

<3>[PASTLOG Err:past_search_reader(459)]Payload size error : offset=5213917 2776

It doesn't show any date stamps so you can't see how often these messages are logged, but I'm guessing there would be one at least every few seconds - maybe even many messages per second.

Searching for a file named pastlog, I found that it is a command, and a device:

Code:

./system/bin:
-rwxr-xr-x root     shell        9824 2011-12-21 07:01 pastlog

./sys/devices/virtual/misc/pastlog:
-rw-r--r-- root     root         4096 2012-07-20 19:43 uevent
-r--r--r-- root     root         4096 2012-07-22 11:52 dev
lrwxrwxrwx root     root              2012-07-22 11:52 subsystem -> ../../../../class/misc
drwxr-xr-x root     root              2012-07-20 19:43 power

./sys/devices/virtual/misc/pastlog/power:
-rw-r--r-- root     root         4096 2012-07-22 11:52 control
-rw-r--r-- root     root         4096 2012-07-22 11:52 wakeup

./sys/dev/char:
lrwxrwxrwx root     root              2012-07-22 11:52 10:46 -> ../../devices/virtual/misc/pastlog

./sys/module:
drwxr-xr-x root     root              2012-07-22 11:52 pastlog

./sys/module/pastlog:
drwxr-xr-x root     root              2012-07-22 11:52 parameters

./sys/module/pastlog/parameters:
-r--r--r-- root     root         4096 2012-07-22 11:52 pastlog_h
-r--r--r-- root     root         4096 2012-07-22 11:52 pastlog_emmc
-r--r--r-- root     root         4096 2012-07-22 11:52 pastlog_state

./dev:
crw-rw-rw- root     root      10,  46 2012-07-20 19:43 pastlog

I tried the "pastlog" command, and was presented with a long log output from Android (apparently this is an Android-level log file, like the syslog is the Linux-level log).

I suspect that this caused the following 2 lines in the syslog and ended the problem:

Code:

<3>[PASTLOG Err:past_read_cache(218)]read error : pos=3177588 size=4096 offset=3176960
<4>[PASTLOG Info:past_search_reader(464)]cannot read -> log buffer reset

JSWolf · 07-22-2012, 03:42 PM

You really should install the latest firmware from Sony as Sony has fixed some serious bugs that the earlier firmware (like the one you have) have. These bugs have to do with the touch. You can expect problems when using a know very buggy firmware.

RhialtoFalu · 07-22-2012, 06:34 PM

Quote:

Originally Posted by JSWolf

You really should install the latest firmware from Sony as Sony has fixed some serious bugs that the earlier firmware (like the one you have) have. These bugs have to do with the touch. You can expect problems when using a know very buggy firmware.

I did install 1.00.04, as I explained in the original post. And I hardly had any of the reported problems with locking up the touch screen anyway.

uboot · 07-23-2012, 02:49 PM

i never had issues with the logging system but I guess your file system might be corrupted. this may occur on improper shutdown, i.e. reset or device crash.

I would try a statically linked e2fsck in recovery console, just in case. you'll find a link in this thread: https://www.mobileread.com/forums/sho...d.php?t=166723

RhialtoFalu · 07-27-2012, 08:03 AM

Quote:

Originally Posted by uboot

I would try a statically linked e2fsck in recovery console, just in case. you'll find a link in this thread: https://www.mobileread.com/forums/sho...d.php?t=166723

That is a good idea. I do see a message in the syslog about mmcblk2p10 being unchecked when mounted. From post #25 I got the proper statically linked version, and it checked the partition. Fortunately it had no complaints.

I wonder if anything changed between firmware 1.00.00 and 1.00.04, since I vaguely seem to recall that I was able to run a dynamically linked e2fsck before (with 1.00.00), the one linked from post #1. (But maybe I remember wrong)

uboot · 07-30-2012, 06:27 AM

A dynamical linked e2fsck must match the ext2 lib on the device. but I can't remember that I was ever able to run a non-static e2fsck...

altruizine · 08-10-2012, 09:11 PM

I have run into the exact same problem as described in the original posting. But unlike RhialtoFalu, I cannot seem to resolve it.

Flushing the log doesn't seem to work for me. Neither running "logcat" nor the "pastlog" command work: Instead, both commands hang hard and and cannot be killed; I have to close the terminal after running them. :-(

Maybe it's possible to clear out the log manually... Any idea where it is kept? The debug messages appear in a source code file linux-2.6.35.3/drivers/staging/pastlog/mmc_past.c, so it's perhaps a static flash partition?

altruizine · 08-11-2012, 05:05 PM

OK, apparently I managed to fix this.

My guess was right, the pastlog (whatever it is; perhaps a copy of the logcat output made persistent across boots?) is saved to a hidden area on the internal flash storage. I was able to find the internal partition table (“raw data table”) on the flash device by looking for its magic value (taken from the kernel source code distributed by Sony), and to find the pastlog area in this table by looking for the “LOG” label (also found in the source code). The referenced pastlog area did indeed contain the pastlog header (replicated two times) with the right magic values.

I fixed the problem by resetting the pastlog headers on disk with all zeros and then rebooting:

Code:

cd /dev/block/ 
dd if=mmcblk2 bs=1 skip=19922944 count=8192 | od -t x4 -t c

Before proceeding, please make sure you are looking at the pastlog header: The magic value 0x4c4b5045 (ASCII “EPKL”) should appear twice in the output.

Now let's clean out the headers and reboot:

Code:

dd if=/dev/zero of=mmcblk2 bs=1 seek=19922944 count=8192 
reboot

(One symptom of the pastlog problem is that reboots often hang. I had to unplug the USB cable and hit the power button once for it to work.)

RhialtoFalu · 02-06-2013, 02:37 PM

I'm adding to this thread because of a variation on the battery drain issue. In this case, I suddenly found that the battery would be empty after about 3 days or so. "Have you tried turning it off an on again?" Yes, and it made no difference.

When I finally looked with adb, and used the pastlog command from the shell, I found that the pastlog was full of messages like this, one per about 10 seconds:

log_radio opening data channel device - /dev/ttyUSB0. retrying...

Some googling taught me that this is from the "RIL", radio interface library. This url tells about that: http://afewe.wordpress.com/android-a...il-in-android/ .

I was thinking about drastic things like killing the RIL daemon, but it turned out that the poor thing was probably confused about whether the WiFi (or phone?!) was on or not: it was trying to open the device to the modem emulation.

Simply turning the WiFi on and off again made problem disappear.

Let's hope it stays unconfused for a while, since I don't know how it got into that state.

07-22-2012, 10:31 AM	#3
RhialtoFalu Member Posts: 21 Karma: 548 Join Date: Oct 2011 Location: The Netherlands Device: PRS-T1	uboot: thanks for that lead. I have been poking at my T1 for the last week or so, and it seems that the problem has resolved "itself". Or at least, I have some idea of what might have fixed it but I'm not 100% sure about that. (I am still in the dark about how the problem started in the first place). Here is the narrative (for the benefit of people having similar problems who might now find this through google): I poked around with BetterBatteryStats (BBS), both while the reader was connected to USB (and charging), and when disconnected. However BBS had a tendency to stop responding as soon as I disconnected the USB cable, so that wasn't terribly useful. Also it managed to write a log file only twice out of many many attempts. BBS showed active kernel wake locks for pretty much most of the time: past_wake_lock for over 90%... that's what apparently kept the reader awake. As already shown above, there was also a "pastlog_thread" being relatively active. "past_wake_lock" was not known by google! Only after several days I thought to look at the linux system log (through the dmesg command). It turned out to contain only lines like this: Code: <3>[PASTLOG Err:past_search_reader(459)]Payload size error : offset=5213917 2776 It doesn't show any date stamps so you can't see how often these messages are logged, but I'm guessing there would be one at least every few seconds - maybe even many messages per second. Searching for a file named pastlog, I found that it is a command, and a device: Code: ./system/bin: -rwxr-xr-x root shell 9824 2011-12-21 07:01 pastlog ./sys/devices/virtual/misc/pastlog: -rw-r--r-- root root 4096 2012-07-20 19:43 uevent -r--r--r-- root root 4096 2012-07-22 11:52 dev lrwxrwxrwx root root 2012-07-22 11:52 subsystem -> ../../../../class/misc drwxr-xr-x root root 2012-07-20 19:43 power ./sys/devices/virtual/misc/pastlog/power: -rw-r--r-- root root 4096 2012-07-22 11:52 control -rw-r--r-- root root 4096 2012-07-22 11:52 wakeup ./sys/dev/char: lrwxrwxrwx root root 2012-07-22 11:52 10:46 -> ../../devices/virtual/misc/pastlog ./sys/module: drwxr-xr-x root root 2012-07-22 11:52 pastlog ./sys/module/pastlog: drwxr-xr-x root root 2012-07-22 11:52 parameters ./sys/module/pastlog/parameters: -r--r--r-- root root 4096 2012-07-22 11:52 pastlog_h -r--r--r-- root root 4096 2012-07-22 11:52 pastlog_emmc -r--r--r-- root root 4096 2012-07-22 11:52 pastlog_state ./dev: crw-rw-rw- root root 10, 46 2012-07-20 19:43 pastlog I tried the "pastlog" command, and was presented with a long log output from Android (apparently this is an Android-level log file, like the syslog is the Linux-level log). I suspect that this caused the following 2 lines in the syslog and ended the problem: Code: <3>[PASTLOG Err:past_read_cache(218)]read error : pos=3177588 size=4096 offset=3176960 <4>[PASTLOG Info:past_search_reader(464)]cannot read -> log buffer reset Last edited by RhialtoFalu; 07-22-2012 at 10:43 AM.

08-11-2012, 05:05 PM	#10
altruizine Senior Altruist Posts: 82 Karma: 600554 Join Date: Jun 2012 Device: Onyx Boox C67ML, Onyx Boox Note Pro	The fix OK, apparently I managed to fix this. My guess was right, the pastlog (whatever it is; perhaps a copy of the logcat output made persistent across boots?) is saved to a hidden area on the internal flash storage. I was able to find the internal partition table (“raw data table”) on the flash device by looking for its magic value (taken from the kernel source code distributed by Sony), and to find the pastlog area in this table by looking for the “LOG” label (also found in the source code). The referenced pastlog area did indeed contain the pastlog header (replicated two times) with the right magic values. I fixed the problem by resetting the pastlog headers on disk with all zeros and then rebooting: Code: cd /dev/block/ dd if=mmcblk2 bs=1 skip=19922944 count=8192 \| od -t x4 -t c Before proceeding, please make sure you are looking at the pastlog header: The magic value 0x4c4b5045 (ASCII “EPKL”) should appear twice in the output. Now let's clean out the headers and reboot: Code: dd if=/dev/zero of=mmcblk2 bs=1 seek=19922944 count=8192 reboot (One symptom of the pastlog problem is that reboots often hang. I had to unplug the USB cable and hit the power button once for it to work.)

Thread Tools	Search this Thread
Show Printable Version Email this Page	Search this Thread: Advanced Search

Similar Threads
Thread	Thread Starter	Forum	Replies	Last Post
PRS-650 battery drain	StanByk	Sony Reader	13	06-25-2011 04:27 PM
Battery Drain	MaudDib	Amazon Kindle	6	02-07-2011 12:28 AM
DR1000 Battery drain with 1.7.1	Gogolo	iRex	11	09-14-2010 06:37 AM
Classic Battery Drain	Pomtroll	Barnes & Noble NOOK	2	07-11-2010 09:58 PM
Battery drain when off?	Avenger	iRex	19	06-17-2009 11:46 AM

07-13-2012, 06:25 AM	#1
RhialtoFalu Member Posts: 21 Karma: 548 Join Date: Oct 2011 Location: The Netherlands Device: PRS-T1	Enormous battery drain [pastlog, pastlog_thread, past_wake_lock, FIXED] First, the context: About a week ago something weird happened with my T1. It had been rooted with Porkupan's sets. I have never installed any firmware updates so it was still the 1.0.00.09720 version. I was just turning a page in CoolReader when I got stuck in a reboot loop. A few seconds the rotating arrows, then a blank screen for a few seconds, and repeating. After a forced reset with a paperclip, the T1 restarted a bit better, but many programs "accidentally terminated": at least BarTab, Keyboard, ADW Launcher... but the original Sony programs seemed to be still working. I have been reading books in this situation for a day or 2. Since this appeared to be more or less a software problem (although it was worrying that this started so suddenly) I thought to do a restore and firmware update. I started out with the official Sony firmware update to 1.0.04 updater, but it didn't want to do anything. (No "updating" appeared on the screen and the firmware version wasn't changed). So, I tried a SD rescue set of Rupor to go to 1.00.04 that way. That also wasn't a 100% success; it was supposed to take 20 minutes but after a few hours I gave up and I reset. It turned out it had reverted to an apparently clean and unrooted version of 1.00.00. Ok, so I tried the Sony updater again and this time it worked, giving me a clean 1.00.04. As I understand it, this update replaces ALL firmware, the kernel, ramdisk, the recovery environment and the Android environment, right? So whatever had been corrupted would have been replaced by now. After that I installed Rupor's AMR and his pack to enable ADB/Apps2SD. All this seemed to work fine. I re-installed CoolReader. However, and now we get to the problem: the battery lasts barely more than overnight now! Even when the reader is in sleep mode, after a few hours more than overnight, it shuts down. The last thing it does is put up a warning screen that the battery has low power, and that it is disabling the network (which wasn't enabled in the first place). Would this be a software problem (some software that keeps running and eating power), or some hardware problem after all? If I try to get a warranty repair/replacement it would be annoying if it was some software issue which I could have fixed myself. Looking at the software angle, here are the first few lines from the output of top in the adb shell. This "pastlog_thread" seems to be running all the time, and 23% system CPU time seems rather high... the reader was supposed to be idle at the time apart from running top and adb over usb. Code: User 0%, System 23%, IOW 0%, IRQ 0% User 2 + Nice 0 + Sys 74 + Idle 234 + IOW 0 + IRQ 0 + SIRQ 0 = 310 PID CPU% S #THR VSS RSS PCY UID Name 1110 13% D 1 0K 0K fg root pastlog_thread 310 8% S 1 0K 0K fg root esdhc_wq/0 2626 3% R 1 948K 388K fg root top 2137 0% S 47 278676K 41256K fg system system_server 5 0% S 1 0K 0K fg root khelper 8 0% S 1 0K 0K fg root async/mgr 9 0% S 1 0K 0K fg root pm 12 0% S 1 0K 0K fg root suspend 76 0% S 1 0K 0K unk root usb_wakeup thre Edit: I also tried the battery recalibration by removing the file /data/system/batterystats.bin. It made no difference. Last edited by RhialtoFalu; 07-22-2012 at 06:36 PM. Reason: update title

07-13-2012, 06:12 PM	#2
uboot Evangelist Posts: 425 Karma: 75216 Join Date: Nov 2011 Location: old europe Device: Kobo Mini, Tolino Epos 2	what about this one: https://www.mobileread.com/forums/sho...d.php?t=181673

07-22-2012, 03:42 PM	#4
JSWolf Resident Curmudgeon Posts: 73,845 Karma: 128597114 Join Date: Nov 2006 Location: Roslindale, Massachusetts Device: Kobo Libra 2, Kobo Aura H2O, PRS-650, PRS-T1, nook STR, PW3	You really should install the latest firmware from Sony as Sony has fixed some serious bugs that the earlier firmware (like the one you have) have. These bugs have to do with the touch. You can expect problems when using a know very buggy firmware.

07-23-2012, 02:49 PM	#6
uboot Evangelist Posts: 425 Karma: 75216 Join Date: Nov 2011 Location: old europe Device: Kobo Mini, Tolino Epos 2	i never had issues with the logging system but I guess your file system might be corrupted. this may occur on improper shutdown, i.e. reset or device crash. I would try a statically linked e2fsck in recovery console, just in case. you'll find a link in this thread: https://www.mobileread.com/forums/sho...d.php?t=166723

07-30-2012, 06:27 AM	#8
uboot Evangelist Posts: 425 Karma: 75216 Join Date: Nov 2011 Location: old europe Device: Kobo Mini, Tolino Epos 2	A dynamical linked e2fsck must match the ext2 lib on the device. but I can't remember that I was ever able to run a non-static e2fsck...

08-10-2012, 09:11 PM	#9
altruizine Senior Altruist Posts: 82 Karma: 600554 Join Date: Jun 2012 Device: Onyx Boox C67ML, Onyx Boox Note Pro	I have run into the exact same problem as described in the original posting. But unlike RhialtoFalu, I cannot seem to resolve it. Flushing the log doesn't seem to work for me. Neither running "logcat" nor the "pastlog" command work: Instead, both commands hang hard and and cannot be killed; I have to close the terminal after running them. :-( Maybe it's possible to clear out the log manually... Any idea where it is kept? The debug messages appear in a source code file linux-2.6.35.3/drivers/staging/pastlog/mmc_past.c, so it's perhaps a static flash partition?

02-06-2013, 02:37 PM	#11
RhialtoFalu Member Posts: 21 Karma: 548 Join Date: Oct 2011 Location: The Netherlands Device: PRS-T1	I'm adding to this thread because of a variation on the battery drain issue. In this case, I suddenly found that the battery would be empty after about 3 days or so. "Have you tried turning it off an on again?" Yes, and it made no difference. When I finally looked with adb, and used the pastlog command from the shell, I found that the pastlog was full of messages like this, one per about 10 seconds: log_radio opening data channel device - /dev/ttyUSB0. retrying... Some googling taught me that this is from the "RIL", radio interface library. This url tells about that: http://afewe.wordpress.com/android-a...il-in-android/ . I was thinking about drastic things like killing the RIL daemon, but it turned out that the poor thing was probably confused about whether the WiFi (or phone?!) was on or not: it was trying to open the device to the modem emulation. Simply turning the WiFi on and off again made problem disappear. Let's hope it stays unconfused for a while, since I don't know how it got into that state.