def fill_memcached_cache(cache):
memcached_time_start = get_memcached_time()
memcached_requests_start = get_memcached_requests()
items_for_memcached = {}
(objects, items_filler, timeout, batch_size) = cache_fillers[cache]
count = 0
for obj in objects():
items_filler(items_for_memcached, obj)
count += 1
if (count % batch_size == 0):
cache_set_many(items_for_memcached, timeout=3600*24)
items_for_memcached = {}
cache_set_many(items_for_memcached, timeout=3600*24*7)
logging.info("Succesfully populated %s cache! Consumed %s memcached queries (%s time)" % \
(cache, get_memcached_requests() - memcached_requests_start,
round(get_memcached_time() - memcached_time_start, 2)))
def record_request_restart_data(log_data):
if settings.PROFILE_ALL_REQUESTS:
log_data["prof"].enable()
log_data['time_restarted'] = time.time()
log_data['memcached_time_restarted'] = get_memcached_time()
log_data['memcached_requests_restarted'] = get_memcached_requests()
log_data['bugdown_time_restarted'] = get_bugdown_time()
log_data['bugdown_requests_restarted'] = get_bugdown_requests()
def record_request_stop_data(log_data):
log_data['time_stopped'] = time.time()
log_data['memcached_time_stopped'] = get_memcached_time()
log_data['memcached_requests_stopped'] = get_memcached_requests()
log_data['bugdown_time_stopped'] = get_bugdown_time()
log_data['bugdown_requests_stopped'] = get_bugdown_requests()
if settings.PROFILE_ALL_REQUESTS:
log_data["prof"].disable()
def record_request_restart_data(log_data):
if settings.PROFILE_ALL_REQUESTS:
log_data["prof"].enable()
log_data['time_restarted'] = time.time()
log_data['memcached_time_restarted'] = get_memcached_time()
log_data['memcached_requests_restarted'] = get_memcached_requests()
log_data['bugdown_time_restarted'] = get_bugdown_time()
log_data['bugdown_requests_restarted'] = get_bugdown_requests()
def record_request_stop_data(log_data):
log_data['time_stopped'] = time.time()
log_data['memcached_time_stopped'] = get_memcached_time()
log_data['memcached_requests_stopped'] = get_memcached_requests()
log_data['bugdown_time_stopped'] = get_bugdown_time()
log_data['bugdown_requests_stopped'] = get_bugdown_requests()
if settings.PROFILE_ALL_REQUESTS:
log_data["prof"].disable()
def write_log_line(log_data, path, method, remote_ip, email, client_name,
status_code=200, error_content=None, error_content_iter=None):
assert error_content is None or error_content_iter is None
if error_content is not None:
error_content_iter = (error_content,)
# For statsd timer name
if path == '/':
statsd_path = 'webreq'
else:
statsd_path = u"webreq.%s" % (path[1:].replace('/', '.'),)
# Remove non-ascii chars from path (there should be none, if there are it's
# because someone manually entered a nonexistant path), as UTF-8 chars make
# statsd sad when it sends the key name over the socket
statsd_path = statsd_path.encode('ascii', errors='ignore')
blacklisted_requests = ['do_confirm', 'send_confirm',
'eventslast_event_id', 'webreq.content', 'avatar', 'user_uploads',
'password.reset', 'static', 'json.bots', 'json.users', 'json.streams',
'accounts.unsubscribe', 'apple-touch-icon', 'emoji', 'json.bots',
'upload_file', 'realm_activity', 'user_activity']
suppress_statsd = any((blacklisted in statsd_path for blacklisted in blacklisted_requests))
time_delta = -1
# A time duration of -1 means the StartLogRequests middleware
# didn't run for some reason
optional_orig_delta = ""
if 'time_started' in log_data:
time_delta = time.time() - log_data['time_started']
if 'time_stopped' in log_data:
orig_time_delta = time_delta
time_delta = ((log_data['time_stopped'] - log_data['time_started']) +
(time.time() - log_data['time_restarted']))
optional_orig_delta = " (lp: %s)" % (format_timedelta(orig_time_delta),)
memcached_output = ""
if 'memcached_time_start' in log_data:
memcached_time_delta = get_memcached_time() - log_data['memcached_time_start']
memcached_count_delta = get_memcached_requests() - log_data['memcached_requests_start']
if 'memcached_requests_stopped' in log_data:
# (now - restarted) + (stopped - start) = (now - start) + (stopped - restarted)
memcached_time_delta += (log_data['memcached_time_stopped'] -
log_data['memcached_time_restarted'])
memcached_count_delta += (log_data['memcached_requests_stopped'] -
log_data['memcached_requests_restarted'])
if (memcached_time_delta > 0.005):
memcached_output = " (mem: %s/%s)" % (format_timedelta(memcached_time_delta),
memcached_count_delta)
if not suppress_statsd:
statsd.timing("%s.memcached.time" % (statsd_path,), timedelta_ms(memcached_time_delta))
statsd.incr("%s.memcached.querycount" % (statsd_path,), memcached_count_delta)
startup_output = ""
if 'startup_time_delta' in log_data and log_data["startup_time_delta"] > 0.005:
startup_output = " (+start: %s)" % (format_timedelta(log_data["startup_time_delta"]))
bugdown_output = ""
if 'bugdown_time_start' in log_data:
bugdown_time_delta = get_bugdown_time() - log_data['bugdown_time_start']
bugdown_count_delta = get_bugdown_requests() - log_data['bugdown_requests_start']
if 'bugdown_requests_stopped' in log_data:
# (now - restarted) + (stopped - start) = (now - start) + (stopped - restarted)
bugdown_time_delta += (log_data['bugdown_time_stopped'] -
log_data['bugdown_time_restarted'])
bugdown_count_delta += (log_data['bugdown_requests_stopped'] -
log_data['bugdown_requests_restarted'])
if (bugdown_time_delta > 0.005):
bugdown_output = " (md: %s/%s)" % (format_timedelta(bugdown_time_delta),
bugdown_count_delta)
if not suppress_statsd:
statsd.timing("%s.markdown.time" % (statsd_path,), timedelta_ms(bugdown_time_delta))
statsd.incr("%s.markdown.count" % (statsd_path,), bugdown_count_delta)
# Get the amount of time spent doing database queries
db_time_output = ""
queries = connection.connection.queries if connection.connection is not None else []
if len(queries) > 0:
query_time = sum(float(query.get('time', 0)) for query in queries)
db_time_output = " (db: %s/%sq)" % (format_timedelta(query_time),
len(queries))
if not suppress_statsd:
# Log ms, db ms, and num queries to statsd
statsd.timing("%s.dbtime" % (statsd_path,), timedelta_ms(query_time))
statsd.incr("%s.dbq" % (statsd_path, ), len(queries))
statsd.timing("%s.total" % (statsd_path,), timedelta_ms(time_delta))
if 'extra' in log_data:
extra_request_data = " %s" % (log_data['extra'],)
else:
extra_request_data = ""
logger_client = "(%s via %s)" % (email, client_name)
logger_timing = '%5s%s%s%s%s%s %s' % \
(format_timedelta(time_delta), optional_orig_delta,
memcached_output, bugdown_output,
db_time_output, startup_output, path)
logger_line = '%-15s %-7s %3d %s%s %s' % \
(remote_ip, method, status_code,
logger_timing, extra_request_data, logger_client)
if (status_code in [200, 304] and method == "GET" and path.startswith("/static")):
logger.debug(logger_line)
else:
logger.info(logger_line)
if (is_slow_query(time_delta, path)):
queue_json_publish("slow_queries", "%s (%s)" % (logger_timing, email), lambda e: None)
if settings.PROFILE_ALL_REQUESTS:
log_data["prof"].disable()
profile_path = "/tmp/profile.data.%s.%s" % (path.split("/")[-1], int(time_delta * 1000),)
log_data["prof"].dump_stats(profile_path)
# Log some additional data whenever we return certain 40x errors
if 400 <= status_code < 500 and status_code not in [401, 404, 405]:
error_content = ''.join(error_content_iter)
if len(error_content) > 100:
error_content = "[content more than 100 characters]"
logger.info('status=%3d, data=%s, uid=%s' % (status_code, error_content, email))
def write_log_line(log_data,
path,
method,
remote_ip,
email,
client_name,
status_code=200,
error_content=None,
error_content_iter=None):
assert error_content is None or error_content_iter is None
if error_content is not None:
error_content_iter = (error_content, )
# For statsd timer name
if path == '/':
statsd_path = u'webreq'
else:
statsd_path = u"webreq.%s" % (path[1:].replace('/', '.'), )
# Remove non-ascii chars from path (there should be none, if there are it's
# because someone manually entered a nonexistant path), as UTF-8 chars make
# statsd sad when it sends the key name over the socket
statsd_path = statsd_path.encode('ascii', errors='ignore')
blacklisted_requests = [
'do_confirm', 'send_confirm', 'eventslast_event_id', 'webreq.content',
'avatar', 'user_uploads', 'password.reset', 'static', 'json.bots',
'json.users', 'json.streams', 'accounts.unsubscribe',
'apple-touch-icon', 'emoji', 'json.bots', 'upload_file',
'realm_activity', 'user_activity'
]
suppress_statsd = any(
(blacklisted in statsd_path for blacklisted in blacklisted_requests))
time_delta = -1
# A time duration of -1 means the StartLogRequests middleware
# didn't run for some reason
optional_orig_delta = ""
if 'time_started' in log_data:
time_delta = time.time() - log_data['time_started']
if 'time_stopped' in log_data:
orig_time_delta = time_delta
time_delta = ((log_data['time_stopped'] - log_data['time_started']) +
(time.time() - log_data['time_restarted']))
optional_orig_delta = " (lp: %s)" % (
format_timedelta(orig_time_delta), )
memcached_output = ""
if 'memcached_time_start' in log_data:
memcached_time_delta = get_memcached_time(
) - log_data['memcached_time_start']
memcached_count_delta = get_memcached_requests(
) - log_data['memcached_requests_start']
if 'memcached_requests_stopped' in log_data:
# (now - restarted) + (stopped - start) = (now - start) + (stopped - restarted)
memcached_time_delta += (log_data['memcached_time_stopped'] -
log_data['memcached_time_restarted'])
memcached_count_delta += (log_data['memcached_requests_stopped'] -
log_data['memcached_requests_restarted'])
if (memcached_time_delta > 0.005):
memcached_output = " (mem: %s/%s)" % (
format_timedelta(memcached_time_delta), memcached_count_delta)
if not suppress_statsd:
statsd.timing("%s.memcached.time" % (statsd_path, ),
timedelta_ms(memcached_time_delta))
statsd.incr("%s.memcached.querycount" % (statsd_path, ),
memcached_count_delta)
startup_output = ""
if 'startup_time_delta' in log_data and log_data[
"startup_time_delta"] > 0.005:
startup_output = " (+start: %s)" % (format_timedelta(
log_data["startup_time_delta"]))
bugdown_output = ""
if 'bugdown_time_start' in log_data:
bugdown_time_delta = get_bugdown_time(
) - log_data['bugdown_time_start']
bugdown_count_delta = get_bugdown_requests(
) - log_data['bugdown_requests_start']
if 'bugdown_requests_stopped' in log_data:
# (now - restarted) + (stopped - start) = (now - start) + (stopped - restarted)
bugdown_time_delta += (log_data['bugdown_time_stopped'] -
log_data['bugdown_time_restarted'])
bugdown_count_delta += (log_data['bugdown_requests_stopped'] -
log_data['bugdown_requests_restarted'])
if (bugdown_time_delta > 0.005):
bugdown_output = " (md: %s/%s)" % (
format_timedelta(bugdown_time_delta), bugdown_count_delta)
if not suppress_statsd:
statsd.timing("%s.markdown.time" % (statsd_path, ),
timedelta_ms(bugdown_time_delta))
statsd.incr("%s.markdown.count" % (statsd_path, ),
bugdown_count_delta)
# Get the amount of time spent doing database queries
db_time_output = ""
queries = connection.connection.queries if connection.connection is not None else []
if len(queries) > 0:
query_time = sum(float(query.get('time', 0)) for query in queries)
db_time_output = " (db: %s/%sq)" % (format_timedelta(query_time),
len(queries))
if not suppress_statsd:
# Log ms, db ms, and num queries to statsd
statsd.timing("%s.dbtime" % (statsd_path, ),
timedelta_ms(query_time))
statsd.incr("%s.dbq" % (statsd_path, ), len(queries))
statsd.timing("%s.total" % (statsd_path, ),
timedelta_ms(time_delta))
if 'extra' in log_data:
extra_request_data = " %s" % (log_data['extra'], )
else:
extra_request_data = ""
logger_client = "(%s via %s)" % (email, client_name)
logger_timing = '%5s%s%s%s%s%s %s' % \
(format_timedelta(time_delta), optional_orig_delta,
memcached_output, bugdown_output,
db_time_output, startup_output, path)
logger_line = '%-15s %-7s %3d %s%s %s' % \
(remote_ip, method, status_code,
logger_timing, extra_request_data, logger_client)
if (status_code in [200, 304] and method == "GET"
and path.startswith("/static")):
logger.debug(logger_line)
else:
logger.info(logger_line)
if (is_slow_query(time_delta, path)):
queue_json_publish("slow_queries", "%s (%s)" % (logger_timing, email),
lambda e: None)
if settings.PROFILE_ALL_REQUESTS:
log_data["prof"].disable()
profile_path = "/tmp/profile.data.%s.%s" % (
path.split("/")[-1],
int(time_delta * 1000),
)
log_data["prof"].dump_stats(profile_path)
# Log some additional data whenever we return certain 40x errors
if 400 <= status_code < 500 and status_code not in [401, 404, 405]:
error_content = ''.join(error_content_iter)
if len(error_content) > 100:
error_content = "[content more than 100 characters]"
logger.info('status=%3d, data=%s, uid=%s' %
(status_code, error_content, email))