Uploaded image for project: 'OpenShift API for Data Protection'
  1. OpenShift API for Data Protection
  2. OADP-1719

Excessively long csi backups when volumesnaphot creation taking 40s instead of 1s

XMLWordPrintable

    • False
    • Hide

      None

      Show
      None
    • False
    • ToDo
    • 0
    • 0
    • Very Likely
    • 0
    • None
    • Unset
    • Unknown
    • Yes

      Description of problem:

      create backup CR using CSI plugin  each  volumesnapshotcontent creation takes around 40sec  so for example :

      for single ns with 100 pods size 32MB each , the backup took 4 hours insted of around 8 min 

       

      Version-Release number of selected component (if applicable):

      oadp-operator-bundle-container-1.2.0-48

      How reproducible:

       

      this error appears 8 min before backup started ( not sure if its related ) :

       time="2023-04-23T10:21:59Z" level=error msg="Current BackupStorageLocations available/unavailable/unknown: 0/0/1)" controller=backup-storage-location logSource="/remote-source/velero/app/pkg/controller/backup_storage_location_controller.go:194"
      

      Actual results:

      those errors appears on the velero log related to the volumesnapshotcontent

      time="2023-04-23T14:22:54Z" level=info msg="Waiting for volumesnapshotcontents snapcontent-8d7c5eba-ce39-4f37-b183-a01d4fe11e60 to have snapshot handle. Retrying in 5s" backup=openshift-adp/backup-csi-
      busybox-perf-single-100-pods-rbd cmd=/plugins/velero-plugin-for-csi logSource="/remote-source/app/internal/util/util.go:177" pluginName=velero-plugin-for-csi
      time="2023-04-23T14:22:59Z" level=info msg="Waiting for volumesnapshotcontents snapcontent-8d7c5eba-ce39-4f37-b183-a01d4fe11e60 to have snapshot handle. Retrying in 5s" backup=openshift-adp/backup-csi-
      busybox-perf-single-100-pods-rbd cmd=/plugins/velero-plugin-for-csi logSource="/remote-source/app/internal/util/util.go:177" pluginName=velero-plugin-for-csi
      time="2023-04-23T14:23:04Z" level=info msg="Waiting for volumesnapshotcontents snapcontent-8d7c5eba-ce39-4f37-b183-a01d4fe11e60 to have snapshot handle. Retrying in 5s" backup=openshift-adp/backup-csi-
      busybox-perf-single-100-pods-rbd cmd=/plugins/velero-plugin-for-csi logSource="/remote-source/app/internal/util/util.go:177" pluginName=velero-plugin-for-csi
      time="2023-04-23T14:23:09Z" level=info msg="Waiting for volumesnapshotcontents snapcontent-8d7c5eba-ce39-4f37-b183-a01d4fe11e60 to have snapshot handle. Retrying in 5s" backup=openshift-adp/backup-csi-
      busybox-perf-single-100-pods-rbd cmd=/plugins/velero-plugin-for-csi logSource="/remote-source/app/internal/util/util.go:177" pluginName=velero-plugin-for-csi
      time="2023-04-23T14:23:14Z" level=info msg="Waiting for volumesnapshotcontents snapcontent-8d7c5eba-ce39-4f37-b183-a01d4fe11e60 to have snapshot handle. Retrying in 5s" backup=openshift-adp/backup-csi-
      busybox-perf-single-100-pods-rbd cmd=/plugins/velero-plugin-for-csi logSource="/remote-source/app/internal/util/util.go:177" pluginName=velero-plugin-for-csi
      time="2023-04-23T14:23:19Z" level=info msg="Waiting for volumesnapshotcontents snapcontent-8d7c5eba-ce39-4f37-b183-a01d4fe11e60 to have snapshot handle. Retrying in 5s" backup=openshift-adp/backup-csi-
      busybox-perf-single-100-pods-rbd cmd=/plugins/velero-plugin-for-csi logSource="/remote-source/app/internal/util/util.go:177" pluginName=velero-plugin-for-csi
      time="2023-04-23T14:23:24Z" level=info msg="Waiting for volumesnapshotcontents snapcontent-8d7c5eba-ce39-4f37-b183-a01d4fe11e60 to have snapshot handle. Retrying in 5s" backup=openshift-adp/backup-csi-
      busybox-perf-single-100-pods-rbd cmd=/plugins/velero-plugin-for-csi logSource="/remote-source/app/internal/util/util.go:177" pluginName=velero-plugin-for-csi
      time="2023-04-23T14:23:29Z" level=info msg="Waiting for volumesnapshotcontents snapcontent-8d7c5eba-ce39-4f37-b183-a01d4fe11e60 to have snapshot handle. Retrying in 5s" backup=openshift-adp/backup-csi-
      busybox-perf-single-100-pods-rbd cmd=/plugins/velero-plugin-for-csi logSource="/remote-source/app/internal/util/util.go:177" pluginName=velero-plugin-for-csi
      time="2023-04-23T14:23:34Z" level=info msg="Waiting for volumesnapshotcontents snapcontent-8d7c5eba-ce39-4f37-b183-a01d4fe11e60 to have snapshot handle. Retrying in 5s" backup=openshift-adp/backup-csi-
      busybox-perf-single-100-pods-rbd cmd=/plugins/velero-plugin-for-csi logSource="/remote-source/app/internal/util/util.go:177" pluginName=velero-plugin-for-csi
      time="2023-04-23T14:23:39Z" level=info msg="Waiting for volumesnapshotcontents snapcontent-8d7c5eba-ce39-4f37-b183-a01d4fe11e60 to have snapshot handle. Retrying in 5s" backup=openshift-adp/backup-csi-
      busybox-perf-single-100-pods-rbd cmd=/plugins/velero-plugin-for-csi logSource="/remote-source/app/internal/util/util.go:177" pluginName=velero-plugin-for-csi
      time="2023-04-23T14:23:44Z" level=info msg="Waiting for volumesnapshotcontents snapcontent-8d7c5eba-ce39-4f37-b183-a01d4fe11e60 to have snapshot handle. Retrying in 5s" backup=openshift-adp/backup-csi-
      busybox-perf-single-100-pods-rbd cmd=/plugins/velero-plugin-for-csi logSource="/remote-source/app/internal/util/util.go:177" pluginName=velero-plugin-for-csi
      time="2023-04-23T14:23:49Z" level=info msg="Waiting for volumesnapshotcontents snapcontent-8d7c5eba-ce39-4f37-b183-a01d4fe11e60 to have snapshot handle. Retrying in 5s" backup=openshift-adp/backup-csi-
      busybox-perf-single-100-pods-rbd cmd=/plugins/velero-plugin-for-csi logSource="/remote-source/app/internal/util/util.go:177" pluginName=velero-plugin-for-csi
      time="2023-04-23T14:23:50Z" level=info msg="Validating BackupStorageLocation" backup-storage-location=openshift-adp/example-velero-1 controller=backup-storage-location logSource="/remote-source/velero/
      app/pkg/controller/backup_storage_location_controller.go:152"
       

       

      Name:         backup-csi-busybox-perf-single-100-pods-rbd
      Namespace:    openshift-adp
      Labels:       velero.io/storage-location=example-velero-1
      Annotations:  velero.io/source-cluster-k8s-gitversion=v1.24.0+3882f8f
                    velero.io/source-cluster-k8s-major-version=1
                    velero.io/source-cluster-k8s-minor-version=24Phase:  Completed
      Namespaces:
        Included:  busybox-perf-single-ns-100-pods
        Excluded:  <none>Resources:
        Included:        *
        Excluded:        <none>
        Cluster-scoped:  autoLabel selector:  <none>Storage Location:  example-velero-1Velero-Native Snapshot PVs:  autoTTL:  720h0m0sCSISnapshotTimeout:    10m0s
      ItemOperationTimeout:  1h0m0sHooks:  <none>Backup Format Version:  1.1.0Started:    2023-04-23 10:29:20 +0000 UTC
      Completed:  2023-04-23 14:24:00 +0000 UTCExpiration:  2023-05-23 10:29:20 +0000 UTCVelero-Native Snapshots: <none included>
       

       

       

      Expected results:

      single ns with 100pods 32MB pvc size should take around 8 min and with this issue the same backup cycle took 4 hours  

      Additional info:
      attched the veleo log and backup CR 

        1. 1719.png
          91 kB
          Tzahi Ashkenazi
        2. backup-csi-busybox-perf-single-100-pods-rbd.log
          4.09 MB
          Tzahi Ashkenazi
        3. backup-csi-busybox-perf-single-100-pods-rbd.txt
          0.9 kB
          Tzahi Ashkenazi
        4. csi-snapshot-controller.log
          9.20 MB
          Mordechai Lehrer
        5. velero-77865fd84c-dql47.log
          4.86 MB
          Tzahi Ashkenazi

              spampatt@redhat.com Shubham Pampattiwar
              tzahia Tzahi Ashkenazi
              Tzahi Ashkenazi Tzahi Ashkenazi
              Votes:
              0 Vote for this issue
              Watchers:
              10 Start watching this issue

                Created:
                Updated:
                Resolved: