环境加载速度异常慢

shenkejie15 commented 10 months ago

bug 描述 环境加载速度异常慢（包括python和R），比如一个包导入可能需要10分钟甚至更久。

复现方法 TODO

在一个基础的 notebook 中未能复现该问题：

期望的行为（可选） 应当在较短时间内完成环境加载操作

环境（可选）

平台版本：1.75.0

额外的上下文信息（可选） 已经确认：

出现问题的 Notebook 本身剩余资源充足
出现问题的 Notebook 所在节点的剩余资源充足

shenkejie15 commented 10 months ago

复现方法

创建一个包含 conda 的 Notebook（例如使用 “registry.ibmc.t9kcloud.cn/dockerhub/t9kpublic/miniconda-22.11.1-notebook:1.72.0-sudo” 镜像），其中 /t9k/mnt 挂载一个 tsz-cephfs 类型的 PVC。测试使用的 YAML 见附录。
运行 conda create --prefix /t9k/mnt/myenv python=3.10，创建 Python 环境并保存在 /t9k/mnt/myenv 中
激活 conda 环境，conda activate /t9k/mnt/myenv
安装一个 python 包，这里以 pandas 为例，pip3 install -i https://pypi.tuna.tsinghua.edu.cn/simple pandas
重启 Notebook（暂停 Notebook，然后恢复）
激活 conda 环境，conda activate /t9k/mnt/myenv
装载 python 包，time python3 -c "import pandas as pd"，查看装载速度。本次装载耗时 43.6 秒，远超预期。

附录

测试结果附图：

补充说明，此时不仅是装载 package，运行任何 Python 命令的耗时均长于预期。

Notebook 完整的 YAML：

apiVersion: tensorstack.dev/v1beta1
kind: Notebook
metadata:
name: s3-pvc-test
namespace: demo
spec:
runMode: running
scheduler:
t9kScheduler:
  queue: default
ssh:
authorized_keys:
- skj-ssh-key
enabled: true
serviceType: ClusterIP
template:
spec:
  containers:
  - command: []
    image: registry.ibmc.t9kcloud.cn/dockerhub/t9kpublic/miniconda-22.11.1-notebook:1.72.0-sudo
    name: notebook
    resources:
      limits:
        cpu: "4"
        memory: 8Gi
      requests:
        cpu: "4"
        memory: 8Gi
    volumeMounts:
    - mountPath: /t9k/mnt
      name: workingdir
    - mountPath: /t9k/s3
      name: datadir-1
  volumes:
  - name: workingdir
    persistentVolumeClaim:
      claimName: test-skj
  - name: datadir-1
    persistentVolumeClaim:
      claimName: skjtest
type: jupyter

shenkejie15 commented 10 months ago

补充：用户测试的结果是需要约 3 min 来加载，暂时未完全复现。

一个猜测是因为用户环境装了更多的 Python 包。

tswangdi commented 10 months ago

使用 cprofile 分析加载过程，按照函数的执行时间排序（不包含调用子函数），结果如下：

    Fri Dec 29 17:54:54 2023    output.dat

         278305 function calls (271625 primitive calls) in 68.904 seconds

   Ordered by: internal time
   List reduced from 2589 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     2160   23.951    0.011   23.951    0.011 {built-in method posix.stat}
      464   19.234    0.041   19.234    0.041 {built-in method io.open_code}
      471   13.028    0.028   13.028    0.028 {method 'read' of '_io.BufferedReader' objects}
    89/87    8.641    0.097    8.781    0.101 {built-in method _imp.create_dynamic}
       66    1.469    0.022    1.469    0.022 {built-in method posix.listdir}
        1    1.099    1.099    1.099    1.099 {built-in method mkl._py_mkl_service.get_version}
    89/55    0.251    0.003    5.462    0.099 {built-in method _imp.exec_dynamic}
      464    0.179    0.000    0.179    0.000 {built-in method marshal.loads}
        1    0.100    0.100    0.100    0.100 {method 'dot' of 'numpy.ndarray' objects}
      586    0.047    0.000   25.596    0.044 <frozen importlib._bootstrap>:921(_find_spec)

分析结果为，文件元数据（metadata）相关的系统调用（stat、open）速度较慢。现在医学所的 ceph 集群正在将数据从 S3 复制到 ceph fs 上，可能因为负载过高导致文件系统元数据服务器（metadata server）的响应速度缓慢。等 ceph 数据复制完毕后，应该可以恢复正常，我们会继续追踪该问题。

临时解决方式：上述数据复制操作会影响 tsz-cephfs 这个 StorageClass，用户可以先使用 tsz-cephfs-ssd StorageClass 创建 PVC，来规避该影响。

另外，环境加载速度缓慢现象仅出现在第一次 Import 包的过程中，在第二次加载不会出现该问题，所以用户也可以借助缓存机制来规避该问题。

t9k / user-support

环境加载速度异常慢 #60