前言

前端程序员几乎每天不是在打log就是在打log的路上,最近就在自己真实项目中遇到了一个console.log的坑,由此记录一下console.log过程中你需要了解的知识,少走弯路。

console.log真的是异步吗?

很多人在开发过程中利用console.log调试都被它“骗过”,在监视一些复杂对象的时候,log呈现给我们的值可能与预期不符,如下:
image-20210613000954349
这时有人直接下定义:console.log是异步的!其实这个问题在《你不知道的javascript中卷》第二部分异步和性能1.1节异步控制台部分有提及:

并没有什么规范或一组需求指定console.* 方法族如何工作——它们并不是JavaScript 正式的一部分,而是由宿主环境(请参考本书的“类型和语法”部分)添加到JavaScript 中的。因此,不同的浏览器和JavaScript 环境可以按照自己的意愿来实现,有时候这会引起混淆。
尤其要提出的是,在某些条件下,某些浏览器的console.log(..) 并不会把传入的内容立即输出。出现这种情况的主要原因是,在许多程序(不只是JavaScript)中,I/O 是非常低速的阻塞部分。所以,(从页面/UI 的角度来说)浏览器在后台异步处理控制台I/O 能够提高性能,这时用户甚至可能根本意识不到其发生。

我们得知道一点,JS中对象是引用类型,每次使用对象时,都只是使用了对象在堆中的引用。

当我们在使用a.b.c = 2改变了对象的属性值时,它在堆中c的值也变成了2,而当我们不展开对象看的时候,console.log打印的是对象当时的快照,所以我们看到的c属性值是没改变之前的1,展开对象时,它其实是重新去内存中读取对象的属性值,所以当我们展开对象后看到的c属性值是2。

结论1

由此可见,console.log打印出来的内容并不是一定百分百可信的内容。一般对于基本类型numberstringbooleannullundefined的输出是可信的。但对于Object等引用类型来说,则就会出现上述异常打印输出。
如果改为console.log(JSON.stringfy(obj))则会打印出当前对象的快照,也就能拿到类似同步下的理想结果。更好的解决方案是使用断点进行调试,在那里执行完全停止,您可以检查每个点的当前值。仅对可序列化和不可变数据使用日志记录。

console.log会影响性能吗?

通过上面的问题,可以反思一下:为什么你可以在控制台打印程序变量的快照?并且是引用类型的值时,展开对象会重新去内存读取对象的值?程序运行完后难道变量不应该被gc回收吗?

在传递给console.log的对象是不能被垃圾回收 ♻️,因为在代码运行之后需要在开发工具能查看对象信息。所以最好不要在生产环境中console.log任何对象。

案例一

可以在控制台印证这一点:

1
2
var Foo = function() {};
console.log(new Foo());

打开控制台Memory调试:

image-20210613001444145

案例二

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
<script>
...

mounted () {
this.handleSignCallback({
type: SIGNATURE_TYPES.SIGNATURE_GET_SIGN_STATUS,
success: true,
result: {
longStr: new Array(1000000).join('*'),
someMethod: function () {
}
}
});
},
methods: {
handleSignCallback(data) {
const { type, result, success } = data;
// do something...
console.log(result) // 返回结果打印
if (true) { // 真实项目中用来判断是否满足条件
this.timer = setTimeout(() => {
this.handleSignCallback({
type: SIGNATURE_TYPES.SIGNATURE_GET_SIGN_STATUS,
success: true,
result: {
longStr: new Array(1000000).join('*'),
someMethod: function () {
}
}
})
clearTimeout(this.timer);
}, 1000)
}
}
}
</script>

真实项目在轮询中需要判断某些逻辑,满足条件了,会延迟几秒继续去请求后台,处理一些数据,直到返回的对象没有满足条件的数据才停止去请求拉数据,期间我想打印返回的数据,于是我加了console.log(result),但是如果数据量大的话,执行一会就会程序崩溃,打开调试控制台->Memory:

image-20210613002808312

js Heap在一直上升,无上限,直至浏览器崩溃;

但是当我注释console.log(result)这行 时,再次观察堆内存情况:

image-20210613003410126

这时堆内存使用情况基本稳定在150左右。

结论2

先给上述问题下个结论:console.log确实会影响网页性能。缘由请结合下述展开问题结合深究。

开发小技巧

针对结论二,大家应该都知道了,生产模式下尽量不要留console.log,也许大家现在公司里可能都是这么做的,但是你真的知道为什么这么做吗?下面举例Vue项目如何统一去除坑爹的console.log:

  1. 安装babel-plugin-transform-remove-console

    npm i babel-plugin-transform-remove-console --dev

  2. 配置babel.config.js插件

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    // babel.config.js文件
    const plugins = []
    // 生产环境移除console
    if(process.env.NODE_ENV === 'production' || process.env.NODE_ENV === 'test') {
    plugins.push("transform-remove-console")
    }
    module.exports = {
    presets: [
    '@vue/app'
    ],
    plugins: [...plugins]
    }

结合案例二做性能调试

这里结合Chrome的Devtools–>Performance做一些分析,操作步骤如下:

  1. 开启Performance的记录
  2. 执行CG按钮,创建基准参考线
  3. 多次点击【click】按钮,新建Leaker对象
  4. 执行CG按钮
  5. 停止记录这里结合Chrome的Devtools–>Performance做一些分析,操作步骤如下:
    1. 开启Performance的记录
    2. 执行CG按钮,创建基准参考线
    3. do something or create Object
    4. 执行CG按钮
    5. 停止记录

clipboard.pngclipboard.png

开启log模式下:

image-20210613081509239

说明:测试代码由于模拟轮询场景,定时器触发频繁,可能出现gc的时间点js Heap高于基准线一点,主要看最后一次的js Heap跟第一次触发的线是不是差不多持平

可以看到这里的js Heap(蓝色线,绿色线是nodes节点数量)一直在升高,并且我手动回收垃圾(gc)也无济于事 ,很明显,发生了内存泄露!

关闭log模式下:

image-20210613082254800

关闭log后,观察js堆内存情况如上:可以看到,手动GC后两个时间点,js Heap基本恢复到同一水平线。

在普通场景下测试,例如开启记录->gc->点击事件,创建对象(N遍)->gc->停止记录,js Heap两个gc时间点基本重合。

内存泄露排查方法二

Heap Profiling可以记录当前的堆内存(heap)的快照,并生成对象的描述文件,该描述文件给出了当时JS运行所用的所有对象,以及这些对象所占用的内存大小、引用的层级关系等等。

JS运行的时候,会有栈内存(stack)和堆内存(heap),当我们new一个类的时候,这个new出来的对象就保存在heap里,而这个对象的引用则存储在stack里。程序通过stack的引用找到这个对象。例如:var a = [1,2,3],a是存储在stack中的引用,heap里存储着内容为[1,2,3]的Array对象。

打开调试工具,点击Memory中的Profiles标签,选中“Take Heap Snapshot”,点击“start”按钮,就可以拍在当前JS的heap快照了。

img

右边视图中列出了heap里的对象列表。

constructor:类名
Distance:对象到根的引用层级距离
Objects Count:该类的对象数
Shallow Size:对象所占内存(不包含内部引用的其他对象所占的内存)
Retained Size:对象所占的总内存(包含····················································)
点击上图左上角的黑圈圈,会出现第二个内存快照
img

将上图框框切换到comparison(对照)选项,该视图列出了当前视图与上一个视图的对象差异

New:新建了多少对象
Deleted:回收了多少对象
Delta:新建的对象个数减去回收的对象个数
重点看closure(闭包),如果#Delta为正数,则表示创建了闭包函数,如果多个快照中都没有变负数,则表示没有销毁闭包。

有趣(无聊)的问题

1
2
while (true)
console.log("hello... there");

运行以上代码,在大约 3 分钟左右的时间内,节点消耗了 1.5GB 的内存。

有人会说,死循环了能不引起内存飙升吗?

那看下面这个:

1
2
3
4
5
def hello():
while True:
print "hello world..."

hello()

Python 永远保持在 3.3MB。

有人可能会想到前面说的,console.log会引起内存泄露,但是前面说了是引用类型会造成内存泄露,这里直接打印字符串,为什么性能也会这么差?

简短回答:控制台输出是缓冲和异步的。并且除了全局内存限制外,缓冲区不受任何限制。因此,它填满缓冲区并死亡。
更多信息在#1741

“缓冲区”是指实际上是异步操作队列的隐式缓冲区。

  1. 连接的检查器客户端将导致console.log()缓冲有限数量的消息
  2. 当您打印的速度比接收器(tty、管道、文件等)可以使用它们的速度快时,Libuv 可以缓冲消息。这是您可以通过调整写入速度来解决的问题。

Libuv Libuv是一个高性能的,事件驱动的异步I/O库,它本身是由C语言编写的,具有很高的可移植性。

结论3

node开发时,在我们写入大型日志条目的情况下,写入文件进行日志记录是迄今为止最好的方法。服务稍后读取日志文件并将其聚合到适当的服务。