设计一套完整的日志系统

该文章属于刘小壮原创,转载请注明:刘小壮


需求

日志对于线上排查问题是非常重要的,很多问题其实是很偶现的,同样的系统版本,同样的设备,可能就是用户的复现,而开发通过相同的操作和设备就是不复现。但是这个问题也不能一直不解决,所以可以通过日志的方式排查问题。可能是后台导致的问题,也可能是客户端逻辑问题,在关键点记录日志可以快速定位问题。

假设我们的用户量是一百万日活,其中有1%的用户使用出现问题,即使这个问题并不是崩溃,就是业务上或播放出现问题。那这部分用户就是一万的用户,一万的用户数量是很庞大的。而且大多数用户在遇到问题后,并不会主动去联系客服,而是转到其他平台上。

虽然我们现在有Kibana网络监控,但是只能排查网络请求是否有问题,用户是否在某个时间请求了服务器,服务器下发的数据是否正确,但是如果定位业务逻辑的问题,还是要客户端记录日志。

现状

我们项目中之前有日志系统,但是从业务和技术的角度来说,存在两个问题。现有的日志系统从业务层角度,需要用户手动导出并发给客服,对用户有不必要的打扰。而且大多数用户并不会答应客服的请求,不会导出日志给客服。从技术的角度,现有的日志系统代码很乱,而且性能很差,导致线上不敢持续记录日志,会导致播放器卡顿。

而且现有的日志系统仅限于debug环境开启主动记录,线上是不开启的,线上出问题后需要用户手动打开,并且记录时长只有三分钟。正是由于现在存在的诸多问题,所以大家对日志的使用并不是很积极,线上排查问题就比较困难。

方案设计


思路

正是针对现在存在的问题,我准备做一套新的日志系统,来替代现有的日志系统。新的日志系统定位很简单,就是纯粹的记录业务日志。Crash、埋点这些,我们都不记录在里面,这些可以当做以后的扩展。日志系统就记录三种日志,业务日志、网络日志、播放器日志。

日志收集我们采用的主动回捞策略,在日志平台上填写用户的uid,通过uid对指定设备下发回捞指令,回捞指令通过长连接的方式下发。客户端收到回捞指令后,根据筛选条件对日志进行筛选,随后以天为单位写入到不同的文件中,压缩后上传到后端。

在日志平台可以根据指定的条件进行搜索,并下载文件查看日志。为了便于开发者查看日志,从数据库取出的日志都会写成.txt形式,并上传此文件。

API设计

对于调用的API设计,应该足够简单,业务层使用时就像调用NSLog一样。所以对于API的设计方案,我采用的是宏定义的方式,调用方法和NSLog一样,调用很简单。

#if DEBUG
#define SVLogDebug(frmt, ...)   [[SVLogManager sharedInstance] mobileLogContent:(frmt), ##__VA_ARGS__]
#else
#define SVLogDebug(frmt, ...)   NSLog(frmt, ...)
#endif

日志总共分为三种类型,业务日志、播放器日志、网络日志,对于三种日志分别对应着不同的宏定义。不同的宏定义,写入数据库的类型也不一样,可以用户日志筛选。

  • 业务日志:SVLogDebug
  • 播放器日志:SVLogDebugPlayer
  • 网络日志:SVLogDebugQUIC

淘汰策略

不光是要往数据库里写,还需要考虑淘汰策略。淘汰策略需要平衡记录的日志数量,以及时效性的问题,日志数量尽量够排查问题,并且还不会占用过多的磁盘空间。所以,在日志上传之后会将已上传日志删除掉,除此之外日志淘汰策略有以下两种。

  1. 日志最多只保存三天,三天以前的日志都会被删掉。在应用启动后进行检查,并后台线程执行这个过程。
  2. 日志增加一个最大阈值,超过阈值的日志部分,以时间为序,从前往后删除。我们定义的阈值大小为200MB,一般不会超过这个大小。

记录基础信息

在排查问题时一些关键信息也很重要,例如用户当时的网络环境,以及一些配置项,这些因素对代码的执行都会有一些影响。对于这个问题,我们也会记录一些用户的配置信息及网络环境,方便排查问题,但不会涉及用户经纬度等隐私信息。

数据库


旧方案

之前的日志方案是通过DDLog实现的,这种方案有很严重的性能问题。其写入日志的方式,是通过NSData来实现的,在沙盒创建一个txt文件,通过一个句柄来向本地写文件,每次写完之后把句柄seek到文件末尾,下次直接在文件末尾继续写入日志。日志是以NSData的方式进行处理的,相当于一直在频繁的进行本地文件写入操作,还要在内存中维持一个或者多个句柄对象。

这种方式还有个问题在于,因为是直接进行二进制写入,在本地存储的是txt文件。这种方式是没有办法做筛选之类的操作的,扩展性很差,所以新的日志方案我们打算采用数据库来实现。

方案选择

我对比了一下iOS平台主流的数据库,发现WCDB是综合性能最好的,某些方面比FMDB都要好,而且由于是C++实现的代码,所以从代码执行的层面来讲,也不会有OC的消息发送和转发的额外消耗。

根据WCDB官网的统计数据,WCDBFMDB进行对比,FMDB是对SQLite进行简单封装的框架,和直接用SQLite差别不是很大。而WCDB则在sqlcipher的基础上进行的深度优化,综合性能比FMDB要高,以下是性能对比,数据来自WCDB官方文档。

单次读操作WCDB要比FMDB5%左右,在for循环内一直读。

单次写操作WCDB要比FMDB28%,一个for循环一直写。

批量写操作比较明显,WCDB要比FMDB180%,一个批量任务写入一批数据。

从数据可以看出,WCDB在写操作这块性能要比FMDB要快很多,而本地日志最频繁的就是写操作,所以这正好符合我们的需求,所以选择WCDB作为新的数据库方案是最合适的。而且项目中曝光模块已经用过WCDB,证明这个方案是可行并且性能很好的。

表设计

我们数据库的表设计很简单,就下面四个字段,不同类型的日志用type做区分。如果想增加新的日志类型,也可以在项目中扩展。因为使用的是数据库,所以扩展性很好。

  • index:主键,用来做索引。
  • content:日志内容,记录日志内容。
  • createTime:创建时间,日志入库的时间。
  • type:日志类型,用来区分三种类型。

数据库优化

我们是视频类应用,会涉及播放、下载、上传等主要功能,这些功能都会大量记录日志,来方便排查线上问题。所以,避免数据库太大就成了我在设计日志系统时,比较看重的一点。

根据日志规模,我对播放、下载、上传三个模块进行了大量测试,播放一天两夜、下载40集电视剧、上传多个高清视频,累计记录的日志数量大概五万多条。我发现数据库文件夹已经到200MB+的大小,这个大小已经是比较大的,所以需要对数据库进行优化。

我观察了一下数据库文件夹,有三个文件,dbshmwal,主要是数据库的日志文件太大,db文件反而并不大。所以需要调用sqlite3_wal_checkpointwal内容写入到数据库中,这样可以减少walshm文件的大小。但WCDB并没有提供直接checkpoint的方法,所以经过调研发现,执行database的关闭操作时,可以触发checkpoint

我在应用程序退出时,监听了terminal通知,并且把处理实际尽量靠后。这样可以保证日志不被遗漏,而且还可以在程序退出时关闭数据库。经过验证,优化后的数据库磁盘占用很小。143,987条数据库,数据库文件大小为34.8MB,压缩后的日志大小为1.4MB,解压后的日志大小为13.6MB

wal模式

这里顺带讲一下wal模式,以方便对数据库有更深入的了解。SQLite3.7版本加入了wal模式,但默认是不开启的,iOS版的WCDBwal模式自动开启,并且做了一些优化。

wal文件负责优化多线程下的并发操作,如果没有wal文件,在传统的delete模式下,数据库的读写操作是互斥的,为了防止写到一半的数据被读到,会等到写操作执行完成后,再执行读操作。而wal文件就是为了解决并发读写的情况,shm文件是对wal文件进行索引的。

SQLite比较常用的deletewal两种模式,这两种模式各有优势。delete是直接读写db-page,读写操作的都是同一份文件,所以读写是互斥的,不支持并发操作。而walappend新的db-page,这样写入速度比较快,而且可以支持并发操作,在写入的同时不读取正在操作的db-page即可。

由于delete模式操作的db-page是离散的,所以在执行批量写操作时,delete模式的性能会差很多,这也就是为什么WCDB的批量写入性能比较好的原因。而wal模式读操作会读取dbwal两个文件,这样会一定程度影响读数据的性能,所以wal的查询性能相对delete模式要差。

使用wal模式需要控制wal文件的db-page数量,如果page数量太大,会导致文件大小不受控制。wal文件并不是一直增加的,根据SQLite的设计,通过checkpoint操作可以将wal文件合并到db文件中。但同步的时机会导致查询操作被阻塞,所以不能频繁执行checkpoint。在WCDB中设置了一个1000的阈值,当page达到1000后才会执行一次checkpoint

这个1000是微信团队的一个经验值,太大会影响读写性能,而且占用过多的磁盘空间。太小会频繁执行checkpoint,导致读写受阻。

# define SQLITE_DEFAULT_WAL_AUTOCHECKPOINT  1000

sqlite3_wal_autocheckpoint(db, SQLITE_DEFAULT_WAL_AUTOCHECKPOINT);

int sqlite3_wal_autocheckpoint(sqlite3 *db, int nFrame){
#ifdef SQLITE_OMIT_WAL
  UNUSED_PARAMETER(db);
  UNUSED_PARAMETER(nFrame);
#else
#ifdef SQLITE_ENABLE_API_ARMOR
  if( !sqlite3SafetyCheckOk(db) ) return SQLITE_MISUSE_BKPT;
#endif
  if( nFrame>0 ){
    sqlite3_wal_hook(db, sqlite3WalDefaultHook, SQLITE_INT_TO_PTR(nFrame));
  }else{
    sqlite3_wal_hook(db, 0, 0);
  }
#endif
  return SQLITE_OK;
}

也可以设置日志文件的大小限制,默认是-1,也就是没限制,journalSizeLimit的意思是,超出的部分会被覆写。尽量不要修改这个文件,可能会导致wal文件损坏。

i64 sqlite3PagerJournalSizeLimit(Pager *pPager, i64 iLimit){
  if( iLimit>=-1 ){
    pPager->journalSizeLimit = iLimit;
    sqlite3WalLimit(pPager->pWal, iLimit);
  }
  return pPager->journalSizeLimit;
}

下发指令


日志平台

日志上报应该做到用户无感知,不需要用户主动配合即可进行日志的自动上传。而且并不是所有的用户日志都需要上报,只有出问题的用户日志才是我们需要的,这样也可以避免服务端的存储资源浪费。对于这些问题,我们开发了日志平台,通过下发上传指令的方式告知客户端上传日志。

我们的日志平台做的比较简单,输入uid对指定的用户下发上传指令,客户端上传日志之后,也可以通过uid进行查询。如上图,下发指令时可以选择下面的日志类型和时间区间,客户端收到指令后会根据这些参数做筛选,如果没选择则是默认参数。搜索时也可以使用这三个参数。

日志平台对应一个服务,点击按钮下发上传指令时,服务会给长连接通道下发一个jsonjson中包含上面的参数,以后也可以用来扩展其他字段。上传日志是以天为单位的,所以在这里可以根据天为单位进行搜索,点击下载可以直接预览日志内容。

长连接通道

指令下发这块我们利用了现有的长连接,当用户反馈问题后,我们会记录下用户的uid,如果技术需要日志进行排查问题时,我们会通过日志平台下发指令。

指令会发送到公共的长连接服务后台,服务会通过长连接通道下发指令,如果指令下发到客户端之后,客户端会回复一个ack消息回复,告知通道已经收到指令,通道会将这条指令从队列中移除。如果此时用户未打开App,则这条指令会在下次用户打开App,和长连接通道建立连接时重新下发。

未完成的上传指令会在队列中,但最多不超过三天,因为超过三天的指令就已经失去其时效性,问题当时可能已经通过其他途径解决。

静默push

用户如果打开App时,日志指令的下发可以通过长连接通道下发。还有一种场景,也是最多的一种场景,用户未打开App怎么解决日志上报的问题,这块我们还在探索中。

当时也调研了美团的日志回捞,美团的方案中包含了静默push的策略,但是经过我们调研之后,发现静默push基本意义不大,只能覆盖一些很小的场景。例如用户App被系统kill掉,或者在后台被挂起等,这种场景对于我们来说并不多见。另外和push组的人也沟通了一下,push组反馈说静默push的到达率有些问题,所以就没采用静默push的策略。

日志上传


分片上传

进行方案设计的时候,由于后端不支持直接展示日志,只能以文件的方式下载下来。所以当时和后端约定的是以天为单位上传日志文件,例如回捞的时间点是,开始时间4月21日19:00,结束时间4月23日21:00。对于这种情况会被分割为三个文件,即每天为一个文件,第一天的文件只包含19:00开始的日志,最后一天的文件只包含到21:00的日志。

这种方案也是分片上传的一种策略,上传时以每个日志文件压缩一个zip文件后上传。这样一方面是保证上传成功率,文件太大会导致成功率下降,另一方面是为了做文件分割。经过观察,每个文件压缩成zip后,文件大小可以控制在500kb以内,500kb这个是我们之前做视频切片上传时的一个经验值,这个经验值是上传成功率和分片数量的一个平衡点。

日志命名使用时间戳为组合,时间单位应该精确到分钟,以方便服务端做时间筛选操作。上传以表单的方式进行提交,上传完成后会删除对应的本地日志。如果上传失败则使用重试策略,每个分片最多上传三次,如果三次都上传失败,则这次上传失败,在其他时机再重新上传。

安全性

为了保证日志的数据安全性,日志上传的请求我们通过https进行传输,但这还是不够的,https依然可以通过其他方式获取到SSL管道的明文信息。所以对于传输的内容,也需要进行加密,选择加密策略时,考虑到性能问题,加密方式采用的对称加密策略。

但对称加密的秘钥是通过非对称加密的方式下发的,并且每个上传指令对应一个唯一的秘钥。客户端先对文件进行压缩,对压缩后的文件进行加密,加密后分片再上传。服务端收到加密文件后,通过秘钥解密得到zip并解压缩。

主动上报

新的日志系统上线后,我们发现回捞成功率只有40%,因为有的用户反馈问题后就失去联系,或者反馈问题后一直没有打开App。对于这个问题,我分析用户反馈问题的途径主要有两大类,一种是用户从系统设置里进去反馈问题,并且和客服沟通后,技术介入排查问题。另一种是用户发生问题后,通过反馈群、App Store评论区、运营等渠道反馈的问题。

这两种方式都适用于日志回捞,但第一种由于有特定的触发条件,也就是用户点击进入反馈界面。所以,对于这种场景反馈问题的用户,我们增加了主动上报的方式。即用户点击反馈时,主动上报以当前时间为结束点,三天内的日志。这样可以把日志上报的成功率提升到90%左右,成功率上来后也会推动更多人接入日志模块,方便排查线上问题。

手动导出

日志上传的方式还包含手动导出,手动导出就是通过某种方式进入调试页面,在调试页面选择对应的日志分享,并且调起系统分享面板,通过对应的渠道分享出去。在新的日志系统之前,就是通过这种方式让用户手动导出日志给客服的,可想而知对用户的打扰有多严重吧。

现在手动导出的方式依然存在,但只用于debug阶段测试和开发同学,手动导出日志来排查问题,线上是不需要用户手动操作的。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 204,445评论 6 478
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,889评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 151,047评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,760评论 1 276
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,745评论 5 367
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,638评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,011评论 3 398
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,669评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,923评论 1 299
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,655评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,740评论 1 330
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,406评论 4 320
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,995评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,961评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,197评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,023评论 2 350
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,483评论 2 342

推荐阅读更多精彩内容