3
Program to automate system entering and resuming from sleep states
5
Copyright (C) 2010,2011 Canonical Ltd.
8
Jeff Lane <jeffrey.lane@canonical.com>
10
This program is free software: you can redistribute it and/or modify
11
it under the terms of the GNU General Public License version 2,
12
as published by the Free Software Foundation.
14
This program is distributed in the hope that it will be useful,
15
but WITHOUT ANY WARRANTY; without even the implied warranty of
16
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
17
GNU General Public License for more details.
19
You should have received a copy of the GNU General Public License
20
along with this program. If not, see <http://www.gnu.org/licenses/>.
27
from subprocess import call
28
from optparse import OptionParser, OptionGroup
32
class ListDictHandler(logging.StreamHandler):
34
Extends logging.StreamHandler to handle list, tuple and dict objects
35
internally, rather than through external code, mainly used for debugging
39
def emit(self, record):
40
if isinstance(record.msg, (list, tuple,)):
41
for msg in record.msg:
42
logger = logging.getLogger(record.name)
43
new_record = logger.makeRecord(record.name, record.levelno,
44
record.pathname, record.lineno, msg, record.args,
45
record.exc_info, record.funcName)
46
logging.StreamHandler.emit(self, new_record)
47
elif isinstance(record.msg, dict):
48
for key, val in record.msg.iteritems():
49
logger = logging.getLogger(record.name)
50
new_msg = '%s: %s' % (key, val)
51
new_record = logger.makeRecord(record.name, record.levelno,
52
record.pathname, record.lineno, new_msg, record.args,
53
record.exc_info, record.funcName)
54
logging.StreamHandler.emit(self, new_record)
56
logging.StreamHandler.emit(self, record)
61
Creates an object to handle the actions necessary for suspend/resume
70
def CanWeSleep(self, mode):
72
Test to see if S3 state is available to us. /proc/acpi/* is old
73
and will be deprecated, using /sys/power to maintain usefulness for
77
states_fh = open('/sys/power/state', 'r', 0)
79
states = states_fh.read().split()
82
logging.debug('The following sleep states were found:')
90
def GetCurrentTime(self):
92
time_fh = open('/sys/class/rtc/rtc0/since_epoch', 'r', 0)
94
time = int(time_fh.read())
99
def SetWakeTime(self, time):
101
Get the current epoch time from /sys/class/rtc/rtc0/since_epoch
102
then add time and write our new wake_alarm time to
103
/sys/class/rtc/rtc0/wakealarm.
105
The math could probably be done better but this method avoids having to
106
worry about whether or not we're using UTC or local time for both the
107
hardware and system clocks.
110
self.last_time = self.GetCurrentTime()
111
logging.debug('Current epoch time: %s' % self.last_time)
113
wakealarm_fh = open('/sys/class/rtc/rtc0/wakealarm', 'w', 0)
116
wakealarm_fh.write('0\n')
119
wakealarm_fh.write('+%s\n' % time)
124
logging.debug('Wake alarm in %s seconds' % time)
126
def DoSuspend(self, mode):
128
Suspend the system and hope it wakes up.
129
Previously tried writing new state to /sys/power/state but that
130
seems to put the system into an uncrecoverable S3 state. So far,
131
pm-suspend seems to be the most reliable way to go.
134
# Set up our start and finish markers
135
self.time_stamp = self.GetCurrentTime()
136
self.start_marker = 'CHECKBOX SLEEP TEST START %s' % self.time_stamp
137
self.end_marker = 'CHECKBOX SLEEP TEST STOP %s' % self.time_stamp
138
self.MarkLog(self.start_marker)
141
status = call('/usr/sbin/pm-suspend')
143
status = call('/usr/sbin/pm-hibernate')
145
logging.debug('Unknown sleep state passed: %s' % mode)
149
logging.debug('Successful suspend')
151
logging.debug('Error while running pm-suspend')
152
self.MarkLog(self.end_marker)
154
def GetResults(self, mode, perf):
156
This will parse /var/log/messages for our start and end markers. Then
157
it'll find a few key phrases that are part of the sleep and resume
158
process, grab their timestamps, Bob's your Uncle and return a
159
three-tuple consisting of: (PASS/FAIL,Sleep elapsed time, Resume
162
# figure out our elapsed time
163
logfile = '/var/log/syslog'
164
log_fh = open(logfile, 'r')
166
run_complete = 'Fail'
167
sleep_start_time = 0.0
169
resume_start_time = 0.0
170
resume_end_time = 0.0
172
while self.start_marker not in line:
173
line = log_fh.readline()
174
if self.start_marker in line:
175
logging.debug("Found Start Marker")
176
loglist = log_fh.readlines()
179
for idx in range(0, len(loglist)):
180
if 'PM: Syncing filesystems' in loglist[idx]:
181
sleep_start_time = re.split('[\[\]]',
182
loglist[idx])[1].strip()
183
logging.debug('Sleep started at %s' % sleep_start_time)
184
if 'ACPI: Low-level resume complete' in loglist[idx]:
185
sleep_end_time = re.split('[\[\]]',
186
loglist[idx - 1])[1].strip()
187
logging.debug('Sleep ended at %s' % sleep_end_time)
188
resume_start_time = re.split('[\[\]]',
189
loglist[idx])[1].strip()
190
logging.debug('Resume started at %s' % resume_start_time)
192
if 'Restarting tasks' in loglist[idx]:
193
resume_end_time = re.split('[\[\]]',
194
loglist[idx])[1].strip()
195
logging.debug('Resume ended at %s' % resume_end_time)
196
if self.end_marker in loglist[idx]:
197
logging.debug('End Marker found, run appears to '
199
run_complete = 'Pass'
202
sleep_elapsed = float(sleep_end_time) - float(sleep_start_time)
203
resume_elapsed = float(resume_end_time) - float(resume_start_time)
204
logging.debug('Sleep elapsed: %.4f seconds' % sleep_elapsed)
205
logging.debug('Resume elapsed: %.4f seconds' % resume_elapsed)
207
if self.end_marker in loglist:
208
logging.debug('End Marker found, '
209
'run appears to have completed')
210
run_complete = 'Pass'
212
resume_elapsed = None
214
return (run_complete, sleep_elapsed, resume_elapsed)
216
def MarkLog(self, marker):
218
Write a stamped marker to syslogd (will appear in /var/log/messages).
219
This is used to calculate the elapsed time for each iteration.
221
syslog(LOG_INFO, '---' + marker + '---')
223
def CheckAlarm(self, mode):
225
A better method for checking if system woke via rtc alarm IRQ. If the
226
system woke via IRQ, then alarm_IRQ will be 'no' and wakealarm will be
227
an empty file. Otherwise, alarm_IRQ should still say yes and wakealarm
228
should still have a number in it (the original alarm time), indicating
229
the system did not wake by alarm IRQ, but by some other means.
232
rtc_fh = open('/proc/driver/rtc', 'r', 0)
233
alarm_fh = open('/sys/class/rtc/rtc0/wakealarm', 'r', 0)
235
rtc_data = rtc_fh.read().splitlines()
236
for item in rtc_data:
237
rtc_entry = item.partition(':')
238
rtc[rtc_entry[0].strip()] = rtc_entry[2].strip()
243
alarm = int(alarm_fh.read())
249
logging.debug('Current RTC entries')
251
logging.debug('Current wakealarm %s' % alarm)
253
# see if there's something in wakealarm or alarm_IRQ
254
# Return True indicating the alarm is still set
255
# Return False indicating the alarm is NOT set.
256
# This is currently held up by a bug in PM scripts that
257
# does not reset alarm_IRQ when waking from hibernate.
258
# https://bugs.launchpad.net/ubuntu/+source/linux/+bug/571977
260
if (alarm is not None) or (rtc['alarm_IRQ'] == 'yes'):
261
logging.debug('alarm is %s' % alarm)
262
logging.debug('rtc says alarm_IRQ: %s' % rtc['alarm_IRQ'])
265
logging.debug('alarm was cleared')
268
# This needs to be changed after we get a way around the
269
# hibernate bug. For now, pretend that the alarm is unset for
271
logging.debug('mode is %s so we\'re skipping success check' % mode)
276
usage = 'Usage: %prog [OPTIONS]'
277
parser = OptionParser(usage)
278
group = OptionGroup(parser, 'This will not work for hibernat testing due' \
279
' to a kernel timestamp bug when doing an S4 ' \
280
'(hibernate/resume) sleep cycle')
281
group.add_option('-p', '--perf',
284
help='Add some output that tells you how long it ' \
285
'takes to enter a sleep state and how long it ' \
287
parser.add_option('-i', '--iterations',
292
help='The number of times to run the suspend/resume \
293
loop. Default is %default')
294
parser.add_option('-w', '--wake-in',
300
help='Sets wake up time (in seconds) in the future \
301
from now. Default is %default.')
302
parser.add_option('-s', '--sleep-state',
307
help='Sets the sleep state to test. Passing mem will \
308
set the sleep state to Suspend-To-Ram or S3. Passing \
309
disk will set the sleep state to Suspend-To-Disk or S4\
310
(hibernate). Default sleep state is %default')
311
parser.add_option('-d', '--debug',
314
help='Choose this to add verbose output for debug \
316
parser.add_option_group(group)
317
(options, args) = parser.parse_args()
318
options_dict = vars(options)
320
if not (os.geteuid() == 0):
321
parser.error("Must be run as root.")
324
# Set up logging handler
325
format = '%(message)s'
326
handler = ListDictHandler(sys.stdout)
327
handler.setFormatter(logging.Formatter(format))
328
handler.setLevel(logging.INFO)
331
logger = logging.getLogger()
332
logger.setLevel(logging.DEBUG)
335
handler.setLevel(logging.DEBUG)
337
logger.addHandler(handler)
338
logging.debug('Running with these options')
339
logging.debug(options_dict)
341
suspender = SuspendTest()
346
# Chcek fo the S3 state availability
347
if not suspender.CanWeSleep(options.mode):
348
logging.error('%s sleep state not supported' % options.mode)
351
logging.debug('%s sleep state supported, continuing test'
354
# We run the following for the number of iterations requested
355
for iteration in range(0, options.iterations):
356
# Set new alarm time and suspend.
357
suspender.SetWakeTime(options.wake_time)
358
suspender.DoSuspend(options.mode)
360
run_result[run_count] = suspender.GetResults(options.mode,
362
if suspender.CheckAlarm(options.mode):
363
logging.debug('The alarm is still set')
368
logging.info('=' * 20 + ' Test Results ' + '=' * 20)
369
logging.info(run_result)
371
for k in run_result.iterkeys():
372
sleep_total += run_result[k][1]
373
resume_total += run_result[k][2]
374
sleep_avg = sleep_total / run_count
375
resume_avg = resume_total / run_count
376
logging.info('Average time to sleep: %.4f' % sleep_avg)
377
logging.info('Average time to resume: %.4f' % resume_avg)
378
for run in run_result.keys():
379
if 'Fail' in run_result[run]:
383
logging.error('%s sleep/resume test cycles failed' %
385
logging.error(run_result)
388
logging.info('Successfully completed %s sleep iterations' %
392
if __name__ == '__main__':
added
removed
provider_bin/sleep_test
